[kamailio/kamailio] [Branch 4.4] Cannot save location after resuming a transaction that has been paused by avapi_async_relay (#622)
Console log: ``` 9(27) INFO: <script>: preparing to resume transaction for processing: 6118 / 1144728330 / resume_auth 9(27) ERROR: <script>: Saving location 9(27) ERROR: <core> [db.c:452]: db_use_table(): invalid parameter value 9(27) ERROR: usrloc [ucontact.c:1137]: db_update_ucontact_ruid(): sql use_table failed 9(27) ERROR: usrloc [ucontact.c:1658]: update_contact_db(): failed to update database 9(27) ERROR: registrar [save.c:776]: update_contacts(): failed to update contact ```
Config script snipset: ``` route[authenticate] { if (!$aU) { xlog("REGISTER without aU = $aU"); www_challenge("$fd", "0"); exit; } evapi_async_relay("{'tindex': $T(id_index), 'tlabel': $T(id_label), 'method': 'authenticate', 'route': 'resume_auth'," "'data': { 'si': '$si', 'fU': '$fU', 'fd': '$fd', 'rU': '$rU', 'aU': '$aU', 'rd': '$rd' }" "}" ); xlog("L_INFO", "suspended transaction: $T(id_index) / $T(id_label)\n"); exit; }
route[resume_auth] { xlog("Saving location\n"); if (!save("location")) { sl_reply_error(); } exit; }
event_route[evapi:message-received] { xlog("received [$evapi(msg)] from $evapi(srcaddr):$evapi(srcport)\n"); jansson_get("tindex", "$evapi(msg)", "$var(tindex)"); jansson_get("tlabel", "$evapi(msg)", "$var(tlabel)"); jansson_get("route", "$evapi(msg)", "$var(next_route)"); xlog("L_INFO", "preparing to resume transaction for processing: $var(tindex) / $var(tlabel) / $var(next_route)\n"); t_continue("$var(tindex)", "$var(tlabel)", "$var(next_route)"); } ```
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622
If you used db_mode 1 for usrloc, then try with the patch ee11732 (or master branch). If all ok, I will backport to branch 4.4.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-219269892
Thank you @miconda for your quick reply. Unfortunately neither the patch, nor the master branch helped. The same error persist.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-219301155
Paste here the output of the command:
``` kamctl ps ```
as well as the error log messages for the same running instance of kamailio in order to correlate them and figure out what process tries to write to database.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-219634144
Output of kamctl ps:
Process:: ID=0 PID=10868 Type=main process - attendant Process:: ID=1 PID=10869 Type=udp receiver child=0 sock=194.177.58.208:5060 Process:: ID=2 PID=10870 Type=udp receiver child=1 sock=194.177.58.208:5060 Process:: ID=3 PID=10871 Type=udp receiver child=2 sock=194.177.58.208:5060 Process:: ID=4 PID=10872 Type=udp receiver child=3 sock=194.177.58.208:5060 Process:: ID=5 PID=10873 Type=udp receiver child=4 sock=194.177.58.208:5060 Process:: ID=6 PID=10874 Type=slow timer Process:: ID=7 PID=10875 Type=timer Process:: ID=8 PID=10876 Type=secondary timer Process:: ID=9 PID=10877 Type=EvAPI Dispatcher Process:: ID=10 PID=10878 Type=EvAPI Worker Process:: ID=11 PID=10879 Type=MI FIFO Process:: ID=12 PID=10880 Type=Dialog Clean Timer Process:: ID=13 PID=10881 Type=TIMER NH Process:: ID=14 PID=10882 Type=tcp main process
Error log messages:
9(10877) ERROR: <core> [db.c:452]: db_use_table(): invalid parameter value 9(10877) ERROR: usrloc [ucontact.c:1137]: db_update_ucontact_ruid(): sql use_table failed 9(10877) ERROR: usrloc [ucontact.c:1658]: update_contact_db(): failed to update database 9(10877) ERROR: registrar [save.c:776]: update_contacts(): failed to update contact
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-222327303
Can you try with the patch referenced above? At this moment it is in master branch, if all ok, then it can be considered for backporting.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-222465035
The avpapi doesn't work anymore with this patch. Kamailio cannot send event to external application and doesn't log any error message.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-222560119
Can you set debug=3 in kamailio.cfg and then make all log messages printed by kamailio available (if they are too big, you can use some pastebin portal and put the link here)?
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-222612863
Any chances to get the debug messages for such case?
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-224199992
Here are the log messages:
2(19) DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up 9(26) DEBUG: evapi [evapi_dispatch.c:493]: evapi_recv_notify(): received [0x7ff88a5c9168] [227:{'tindex': 35872, 'tlabel': 41565682, 'method': 'handle_register', 'route': 'resume_register'] (232) 9(26) DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event route for frame: [{"tlabel": 4156 5682, "route": "resume_register"}, "tindex": 35872}] (136) 9(26) ERROR: <script>: received [{"tlabel": 41565682, "route": "resume_register"}, "tindex": 35872}] from 127.0.0.1:58050 9(26) INFO: <script>: preparing to resume transaction for processing: 35872 / 41565682 / resume_register 9(26) DEBUG: tm [t_lookup.c:1574]: t_lookup_ident(): DEBUG: t_lookup_ident: transaction found 9(26) DEBUG: <core> [parser/parse_addr_spec.c:172]: parse_to_param(): DEBUG: add_param: tag=M9pe6mRJ1tataga30 9(26) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec(): end of header reached, state=29 9(26) DEBUG: auth [api.c:84]: pre_auth(): auth: digest-algo: parsed value: 0 9(26) DEBUG: auth [auth_mod.c:505]: pv_authenticate(): HA1 string calculated: 1b8c2561bb3093441d80e656f1c80153 9(26) DEBUG: auth [api.c:199]: auth_check_response(): check_response: Our result = '16250be96870ee37e4316eee3de83 8c1' 9(26) DEBUG: auth [api.c:206]: auth_check_response(): check_response: Authorization is OK 9(26) DEBUG: <core> [msg_translator.c:158]: check_via_address(): (80.12.55.174, 10.153.195.174, 0) 9(26) ERROR: <script>: Fixing NATed register for 1000 before saving location 9(26) ERROR: <script>: Saving location 9(26) DEBUG: registrar [save.c:314]: pack_ci(): set instance[urn:uuid:BEF54D96-103D-29B7-28CE-BC416E756BE1] 9(26) DEBUG: <core> [sruid.c:183]: sruid_next(): new sruid is [uloc-5756e3e7-11-6] (6 / 18) 9(26) DEBUG: registrar [save.c:410]: pack_ci(): generated ruid is: uloc-5756e3e7-11-6 9(26) DEBUG: <core> [sruid.c:183]: sruid_next(): new sruid is [uloc-5756e3e7-11-7] (7 / 18) 9(26) DEBUG: registrar [save.c:410]: pack_ci(): generated ruid is: uloc-5756e3e7-11-7 9(26) DEBUG: usrloc [ucontact.c:1004]: db_update_ucontact_ruid(): ruid:uloc-5756e3e7-11-3 9(26) DEBUG: usrloc [ucontact.c:1133]: db_update_ucontact_ruid(): contact:sip:1000@10.153.195.174:54236 9(26) ERROR: <core> [db.c:452]: db_use_table(): invalid parameter value 9(26) ERROR: usrloc [ucontact.c:1137]: db_update_ucontact_ruid(): sql use_table failed 9(26) ERROR: usrloc [ucontact.c:1658]: update_contact_db(): failed to update database 9(26) ERROR: registrar [save.c:776]: update_contacts(): failed to update contact
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-224346248
Please find it here: http://pastebin.com/raw/ky0iyStt
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-224348905
You said: "Kamailio cannot send event to external application and doesn't log any error message"
But the logs show that the event message was sent out, a response was received and processed, but then the save() failed.
It looks like you run the version before the commits.
Are you trying with master branch?
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-224389974
My bad, let me try again with master branch tonight.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-224832908
I get this log from the event_route[evapi:connection-new] route block bellow:
Jun 10 00:30:57 opensips /home/neotiq/flexproxy/sbin/kamailio[14776]: ERROR: `<script>`: new connection from 127.0.0.1:36993 Jun 10 00:30:57 opensips /home/neotiq/flexproxy/sbin/kamailio[14776]: ERROR: evapi [evapi_dispatch.c:694]: _evapi_relay(): *failed to pass the pointer to evapi dispatcher* Jun 10 00:30:57 opensips /home/neotiq/flexproxy/sbin/kamailio[14776]: ERROR: evapi [evapi_mod.c:252]: w_evapi_relay(): failed to relay event: abcd
The event route block: ``` event_route[evapi:connection-new] { xlog("new connection from $evapi(srcaddr):$evapi(srcport)\n"); evapi_relay("abcd"); } ```
Other calls to evapi_async_relay doesn't log any error but other side received nothing: http://pastebin.com/raw/8AcJA2u1
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-225051022
@miconda I wanted to let you know I was experiencing the same issue on 4.4 when using `http_async_query` but switching to master has fixed the issue.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-228411490
Closed #622.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#event-714510854
But the error in the comment with the example repasted below is not about save anymore -- the example:
``` event_route[evapi:connection-new] { xlog("new connection from $evapi(srcaddr):$evapi(srcport)\n"); evapi_relay("abcd"); } ```
You try to relay an event on the event_route of opening a new connection to evapi, which is not possible, at that moment you are only in the context of new connection -- accept it or not.
You should do evapi_relay() from another worker process, not from the evapi dispatcher process.
If you still get the error with the save() for registration when receiving the response from evapi app, reopen and paste the relevant error messages and config snippets.
--- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/622#issuecomment-230810740
-
Colin Morelli -
Daniel-Constantin Mierla
-
Minh PHAN