Hello,

first a quick check: is route[li] supposed to be route[magic]? Otherwise it is missing from your example.

Cheers, Daniel

On 03.07.17 10:04, Sebastian Damm wrote:

Hi again,

since there really isn't much to find about the lock() function, can somebody tell me if my assumptions about how it should work are wrong? Daniel?

Best Regards, Sebastian

On Wed, Jun 28, 2017 at 1:39 PM, Sebastian Damm damm@sipgate.de wrote:

...

Hi,

for a project I need to make sure, I have a setup where I get mirror-traffic into Kamailio which has to do something with it. To work correctly, I need to make sure, the initial INVITE is processed correctly before any reply to the same call. So I thought I use lock() and unlock() for it.

This is what the relevant kamailio.cfg part looks like:

request_route { xlog("L_INFO", "Got new packet $rm: $si => $Ri\n"); route(li); }

onreply_route { xlog("L_INFO", "Got new packet $rm: $si => $Ri - Reply Code $rs\n"); route(li); }

route[magic] { lock("$ci"); xlog("L_INFO", "Obtained lock, calling lua...\n"); if(!lua_run("handle_packet")) { xlog("L_ERR", "SCRIPT: failed to execute lua function!\n"); } unlock("$ci"); xlog("L_INFO", "Lua finished, released lock...\n");

drop; exit; }

And this is what the log says:

Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Got new packet INVITE: 172.20.21.247 => 172.20.21.4 Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some logging Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Got new packet INVITE: 172.20.21.4 => 172.20.21.247 - Reply Code 407 Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Lua finished, released lock... Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some more logging

As far as I understand the documentation, the second packet should wait for the lock on the Call-ID before executing the lua function. So process 18836 should finish its lua execution before 18837 can do anything further. Did I completely misunderstand the lock() function?

I'm using Kamailio 5.0.2.

Thanks for helping me understand what Kamailio is doing here.

Best Regards, Sebastian

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

Hello,

the last log message is outside of the lock()/unlock(), so it can printed whenever the OS decides to allocate CPU for it. You should move it inside the locked block, but then also be sure the syslog is not asynchronous, because then it can be syslog changing the order.

Also, unrelated, you should not use drop, unless you want to drop the response and not sending it out. For request is not making any difference compared with exit.

Cheers, Daniel

On 03.07.17 10:30, Sebastian Damm wrote:

Hi,

yes, it is. I'm really bad in fixing my configuration for the mailing list or the bugtracker. But those two route calls do call route[magic].

Best Regards, Sebastian

On Mon, Jul 3, 2017 at 10:23 AM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Hello,

first a quick check: is route[li] supposed to be route[magic]? Otherwise it is missing from your example.

Cheers, Daniel

On 03.07.17 10:04, Sebastian Damm wrote:

...

Hi again,

since there really isn't much to find about the lock() function, can somebody tell me if my assumptions about how it should work are wrong? Daniel?

Best Regards, Sebastian

On Wed, Jun 28, 2017 at 1:39 PM, Sebastian Damm damm@sipgate.de wrote:

...

Hi,

for a project I need to make sure, I have a setup where I get mirror-traffic into Kamailio which has to do something with it. To work correctly, I need to make sure, the initial INVITE is processed correctly before any reply to the same call. So I thought I use lock() and unlock() for it.

This is what the relevant kamailio.cfg part looks like:

request_route { xlog("L_INFO", "Got new packet $rm: $si => $Ri\n"); route(li); }

onreply_route { xlog("L_INFO", "Got new packet $rm: $si => $Ri - Reply Code $rs\n"); route(li); }

route[magic] { lock("$ci"); xlog("L_INFO", "Obtained lock, calling lua...\n"); if(!lua_run("handle_packet")) { xlog("L_ERR", "SCRIPT: failed to execute lua function!\n"); } unlock("$ci"); xlog("L_INFO", "Lua finished, released lock...\n");

drop; exit; }

And this is what the log says:

Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Got new packet INVITE: 172.20.21.247 => 172.20.21.4 Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some logging Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Got new packet INVITE: 172.20.21.4 => 172.20.21.247 - Reply Code 407 Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Lua finished, released lock... Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some more logging

As far as I understand the documentation, the second packet should wait for the lock on the Call-ID before executing the lua function. So process 18836 should finish its lua execution before 18837 can do anything further. Did I completely misunderstand the lock() function?

I'm using Kamailio 5.0.2.

Thanks for helping me understand what Kamailio is doing here.

Best Regards, Sebastian

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla www.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio Advanced Training - www.asipto.com Kamailio World Conference - www.kamailioworld.com

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

Hello,

your log message saying that the lock is released is printed after unlock(). When unlock() is executed, the process can lose the CPU and the other process enters the lock() and does its stuff, can even overtake the first process and printing that it released the lock, nothing is guaranteed outside of lock()/unlock(), it is OS scheduler deciding what to do.

Cheers, Daniel

On 03.07.17 12:12, Sebastian Damm wrote:

Hi Daniel,

thanks for the reply.

On Mon, Jul 3, 2017 at 11:57 AM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

the last log message is outside of the lock()/unlock(), so it can printed whenever the OS decides to allocate CPU for it. You should move it inside the locked block, but then also be sure the syslog is not asynchronous, because then it can be syslog changing the order.

Well but shouldn't it be printed only after the lua block was executed? It still looks like the second packet didn't wait for the first packet to release the lock.

My problem is, that I'm writing entries into a hash table if some conditions of an INVITE matches. But the 100 Trying often comes in before the processing of the INVITE is finished. So it is dropped because the reference in the hash table is missing. That's why I wanted to have locking. The second process shouldn't print out "Obtained lock" until the other one has released the lock. And since the first process is still within it's lua logic, I'm pretty sure the lock has not been released.

...

Also, unrelated, you should not use drop, unless you want to drop the response and not sending it out. For request is not making any difference compared with exit.

Actually, I want to drop every packet on the system, because it is only a sniffer that does something with the sniffed packets.

Best Regards, Sebastian

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

I don't get to which log messages are you referring not being printed correctly. Maybe you can add numbers in front of each message and then list what's the order you expect.

Cheers, Daniel

On 03.07.17 12:58, Sebastian Damm wrote:

Okay, I understand. But even after processing the second packet finished, there are still messages coming from the lua script processing the first packet. And those log lines come from within the lock.

I would expect that the log lines look like that:

Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Got new packet INVITE: 172.20.21.247 => 172.20.21.4 Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some logging Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Got new packet INVITE: 172.20.21.4 => 172.20.21.247 - Reply Code 407 Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some more logging Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): lua finished Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Lua finished, released lock... Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Obtained lock, calling lua... Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Lua finished, released lock...

While I agree that the last line for process 18336 could appear later, the other lines should appear before 18337 can obtain the lock.

Best Regards, Sebastian

On Mon, Jul 3, 2017 at 12:20 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Hello,

your log message saying that the lock is released is printed after unlock(). When unlock() is executed, the process can lose the CPU and the other process enters the lock() and does its stuff, can even overtake the first process and printing that it released the lock, nothing is guaranteed outside of lock()/unlock(), it is OS scheduler deciding what to do.

Cheers, Daniel

On 03.07.17 12:12, Sebastian Damm wrote:

...

Hi Daniel,

thanks for the reply.

On Mon, Jul 3, 2017 at 11:57 AM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

the last log message is outside of the lock()/unlock(), so it can printed whenever the OS decides to allocate CPU for it. You should move it inside the locked block, but then also be sure the syslog is not asynchronous, because then it can be syslog changing the order.

Well but shouldn't it be printed only after the lua block was executed? It still looks like the second packet didn't wait for the first packet to release the lock.

My problem is, that I'm writing entries into a hash table if some conditions of an INVITE matches. But the 100 Trying often comes in before the processing of the INVITE is finished. So it is dropped because the reference in the hash table is missing. That's why I wanted to have locking. The second process shouldn't print out "Obtained lock" until the other one has released the lock. And since the first process is still within it's lua logic, I'm pretty sure the lock has not been released.

...

Also, unrelated, you should not use drop, unless you want to drop the response and not sending it out. For request is not making any difference compared with exit.

Actually, I want to drop every packet on the system, because it is only a sniffer that does something with the sniffed packets.

Best Regards, Sebastian

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla www.twitter.com/miconda -- www.linkedin.com/in/miconda Kamailio Advanced Training - www.asipto.com Kamailio World Conference - www.kamailioworld.com

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

Ok, I mixed the part with logs from lua, thinking that there were some not presented in your example and you just generically referred to them. Your simplified example is now clear, I will try to reproduce with it.

Meanwhile, the one thing you cans till check is to be sure $ci is the same in both cases, print it with xlog, but within some chars (quotes, parenthesis) to be sure the is no white space around it.

Cheers, Daniel

On 03.07.17 14:43, Sebastian Damm wrote:

Okay, this is the order from my first mail:

(1) Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Got new packet INVITE: 172.20.21.247 => 172.20.21.4 (2) Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: <script>: Obtained lock, calling lua... (3) Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some logging (4) Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Got new packet INVITE: 172.20.21.4 => 172.20.21.247 - Reply Code 407 (5) Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Obtained lock, calling lua... (6) Jun 28 13:27:04 busch /usr/sbin/kamailio[18837]: INFO: <script>: Lua finished, released lock... (7) Jun 28 13:27:04 busch /usr/sbin/kamailio[18836]: INFO: app_lua [app_lua_sr.c:98]: lua_sr_log(): some more logging

You see, there are 2 PIDs involved, 18836 and 18837. PID 18836 gets the initial INVITE ands starts working. Gets the lock (2). In line (3), app_lua logs stuff. Now in line (4) the 407 comes in. PID 18837 starts working on it. Now it trys to lock the Call-ID, and apparently it can get it. But why? You can see in line (7), that PID 18836 is still in the lua code, so within the locked part of the config. I think, the correct order would be (1) - (2) - (3) - (4) - (7) - (8) - (5) - (6), with (8) being the "released lock" message from PID 18836. The lines 5 and 6 should'nt be printed before the lock is returned.

I have simplified my code for easier understanding. Threw out lua and all stuff, just used sleep from the cfgutils package.

This is what the code looks like:

request_route { xlog("L_INFO", "Got new request ($ci) $rm: $si => $Ri\n"); route(magic); }

onreply_route { xlog("L_INFO", "Got new reply ($ci) $rm: $si => $Ri - Reply Code $rs\n"); route(magic); }

route[magic] { lock("$ci"); xlog("L_INFO", "Obtained lock, sleeping for a second...\n"); sleep("1");

    xlog("L_INFO", "Done sleeping, releasing lock...\n");
    unlock("$ci");
    xlog("L_INFO", "Released lock...\n");

    drop;
    exit;

}

And this is what the logs say: Jul 3 14:36:06 busch /usr/sbin/kamailio[12273]: INFO: <script>: Got new request (313439393038353336363236313137-2m3hb9h5v6o9) INVITE: 172.20.21.200 => 172.20.21.4 Jul 3 14:36:06 busch /usr/sbin/kamailio[12273]: INFO: <script>: Obtained lock, sleeping for a second... Jul 3 14:36:06 busch /usr/sbin/kamailio[12276]: INFO: <script>: Got new reply (313439393038353336363236313137-2m3hb9h5v6o9) INVITE: 172.20.21.4 => 172.20.21.200 - Reply Code 407 Jul 3 14:36:06 busch /usr/sbin/kamailio[12276]: INFO: <script>: Obtained lock, sleeping for a second... Jul 3 14:36:07 busch /usr/sbin/kamailio[12273]: INFO: <script>: Done sleeping, releasing lock... Jul 3 14:36:07 busch /usr/sbin/kamailio[12273]: INFO: <script>: Released lock... Jul 3 14:36:07 busch /usr/sbin/kamailio[12276]: INFO: <script>: Done sleeping, releasing lock... Jul 3 14:36:07 busch /usr/sbin/kamailio[12276]: INFO: <script>: Released lock...

As you can see, both PIDs get the lock on the Call-ID simultaneously. From what I think the lock() function should do, the second PID should wait for the first one to release the lock.

Best Regards, Sebastian

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

Can you paste here the parameters for cfgutils module related to locks?

Cheers, Daniel

On 03.07.17 15:29, Sebastian Damm wrote:

On Mon, Jul 3, 2017 at 3:05 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Meanwhile, the one thing you cans till check is to be sure $ci is the same in both cases, print it with xlog, but within some chars (quotes, parenthesis) to be sure the is no white space around it.

In my latest example, without lua and just with "sleep" in there, I have enclosed $ci in parentheses, so you see it is actually the same Call-ID. I tried raising the log level to debug, too, but nothing gets printed out when the lock() function is being called.

---

Kamailio (SER) - Users Mailing List sr-users@lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

On 03.07.17 17:01, Sebastian Damm wrote:

Hi,

On Mon, Jul 3, 2017 at 4:22 PM, Daniel-Constantin Mierla miconda@gmail.com wrote:

...

Can you paste here the parameters for cfgutils module related to locks?

Wow, that's what I missed. I didn't set any parameter at all. I didn't expect the locking to not work at all if I don't set it. I thought there was a reasonable default value, which I only have to tune if needed. After setting

modparam("cfgutils", "lock_set_size", 4)

the locking works as expected. Maybe that should be added to documentation. I'll create a PR.

So I should set the size to something greater than the amount of concurrent locks expected later? Is there a maximum?

As I looked at code a bit earlier, I noticed that it was silent (just returning -1/false) when the locks set was not initialized. I pushed a patch to log some error messages in this case, so people can become aware what's going on.

Feel free to make a PR with enhancements to the docs.

Cheers, Daniel