Hi,
I upgraded our system to Kamailio 3.3 to take advantage of the new db_cluster module. Currently we have two registration/location servers each with their own sql-server. Authenticated REGISTER messages are forwarded to the other server, which uses the 0x02 flag to save() in order to store it without generating an extra reply. This works fine.
My goal was to use db_cluster to update both databases at once with save() and use the failover mode when reading with lookup(). Have anyone tested a similar setup?
Anyhow, here is how I tried to do it:
modparam("db_cluster","connection","voip1_data2=>postgres://user:pass@hostname1/voipt1_data2") modparam("db_cluster","connection","voip2_data2=>postgres://user:pass@hostname2/voipt2_data2") modparam("db_cluster", "cluster", "data2=>voip1_data2=8s7p;voip2_data2=9s7p")
modparam("usrloc", "db_mode", 2) modparam("usrloc", "db_url", "cluster://data2")
But I get:
: : <core> [pass_fd.c:293]: ERROR: receive_fd: EOF on 33 : ALERT: <core> [main.c:785]: child process 28275 exited by a signal 11 : ALERT: <core> [main.c:788]: core was generated : INFO: <core> [main.c:800]: INFO: terminating due to SIGCHLD
Same with db_mode = 1 or 3, and either modparam("db_cluster", "cluster", "data2=>voip1_data2=8s9p") or modparam("db_cluster", "cluster", "data2=>voip2_data2=8s9p").
No difference between newly booted phones or phones reregistering.
Backtrace from gdb:
(gdb) bt #0 0x002fd7da in db_cluster_insert (_h=0xb7d2dc88, _k=0xbf9ac954, _v=0xbf9ac7ec, _n=18) at dbcl_api.c:334 #1 0x00fbb1cc in db_insert_ucontact (_c=0xb5d828d8) at ucontact.c:565 #2 0x00fcfc5d in insert_ucontact (_r=0xfd3a00, _contact=0xb7d3ce90, _ci=0xc5cc80, _c=0xbf9acb84) at urecord.c:478 #3 0x00c55bb0 in add_contacts (_m=0xb7d05e40, _d=0xb5d63060, _cflags=0, _uri=0x0) at save.c:493 #4 save (_m=0xb7d05e40, _d=0xb5d63060, _cflags=0, _uri=0x0) at save.c:864 #5 0x00c4dd43 in w_save2 (_m=0xb7d05e40, _d=0xb5d63060 "00ֵ", _cflags=0x0) at reg_mod.c:407 #6 0x080586ad in do_action (h=0xbf9acf48, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1157 #7 0x0805fe5c in run_actions (h=0xbf9acf48, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1644 #8 0x080604e1 in run_actions_safe (h=0xbf9adcb8, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1708 #9 0x080f96b7 in rval_get_int (h=0xbf9adcb8, msg=0xbf9ac954, i=0xbf9ad268, rv=0xb7c406cc, cache=0x0) at rvalue.c:920 #10 0x080fcf38 in rval_expr_eval_int (h=0xbf9adcb8, msg=0xb7d05e40, res=0xbf9ad268, rve=0xb7c406c8) at rvalue.c:1914 #11 0x080fd009 in rval_expr_eval_int (h=0xbf9adcb8, msg=0xb7d05e40, res=0xbf9ad544, rve=0xb7c40a70) at rvalue.c:1922 #12 0x080585fe in do_action (h=0xbf9adcb8, a=0xb7c41550, msg=0xb7d05e40) at action.c:1121 #13 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7c41550, msg=0xb7d05e40) at action.c:1644 #14 0x08058657 in do_action (h=0xbf9adcb8, a=0xb7c41650, msg=0xb7d05e40) at action.c:1136 #15 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7c41650, msg=0xb7d05e40) at action.c:1644 #16 0x0805853d in do_action (h=0xbf9adcb8, a=0xb7bd64d8, msg=0xb7d05e40) at action.c:761 #17 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7bc7128, msg=0xb7d05e40) at action.c:1644 #18 0x08060464 in run_top_route (a=0xb7bc7128, msg=0xb7d05e40, c=0x0) at action.c:1729 #19 0x080e11e4 in receive_msg (buf=0x82c4f20 "REGISTER sip:hometest.voip.uio.no SIP/2.0\r\nVia: SIP/2.0/UDP 193.157.149.56;branch=z9hG4bKb8e88f2eE34DCDDD\r\nFrom: "kolbutest" sip:2549619@hometest.voip.uio.no;tag=34CE9BA6-70FCC135\r\nTo: <sip:2549619@"..., len=809, rcv_info=0xbf9ade98) at receive.c:209 #20 0x08177f7b in udp_rcv_loop () at udp_server.c:544 #21 0x080b0426 in main_loop () at main.c:1633 #22 0x080b3d02 in main (argc=17, argv=0xbf9ae174) at main.c:2546
Core dumps and debug logs (debug=3) are available.
On 2012-08-22 at 15:32, Øyvind Kolbu wrote: [...]
Some more details:
# kamailio -V version: kamailio 3.3.1 (i386/linux) aae4e4 flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: aae4e4 compiled on 16:30:51 Aug 21 2012 with gcc 4.1.2
Kamailio 3.3 branch as of git fb51d3815292c27245b26d1f4a4f6c9b190f9200.
Hello,
can you send the output of 'bt full' from gdb?
Simple bt shows only the line where a define is executed, hopefully bt full will get the values from the inside defines to spot the problem.
Also, can you give it a quick try with 9p instead of 7p for both connections?
Cheers, Daniel
On 8/22/12 3:37 PM, Øyvind Kolbu wrote:
On 2012-08-22 at 15:32, Øyvind Kolbu wrote: [...]
Some more details:
# kamailio -V version: kamailio 3.3.1 (i386/linux) aae4e4 flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, F_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: aae4e4 compiled on 16:30:51 Aug 21 2012 with gcc 4.1.2
Kamailio 3.3 branch as of git fb51d3815292c27245b26d1f4a4f6c9b190f9200.
On 2012-08-22 at 16:01, Daniel-Constantin Mierla wrote:
Hello,
can you send the output of 'bt full' from gdb?
#0 0x002fd7da in db_cluster_insert (_h=0xb7d2dc88, _k=0xbf9ac954, _v=0xbf9ac7ec, _n=18) at dbcl_api.c:334 ret = -1 i = 7 k = -1212405280 rc = 8 rok = 0 j = 10624544 cls = 0xb7bc29e0 #1 0x00fbb1cc in db_insert_ucontact (_c=0xb5d828d8) at ucontact.c:565 keys = {0xfd3400, 0xfd3410, 0xfd3418, 0xfd3420, 0xfd3428, 0xfd3430, 0xfd3438, 0xfd3440, 0xfd3448, 0xfd3450, 0xfd3458, 0xfd3460, 0xfd3468, 0xfd3480, 0xfd33f8, 0xfd3470, 0xfd3478, 0xfd3408} vals = {{type = DB1_STR, nul = 0, free = 174331528, val = {int_val = 12962272, ll_val = 30077733344, double_val = 1.4860374750044156e-313, time_val = 12962272, string_val = 0xc5c9e0 "2549619@hometest.voip.uio.no", str_val = { s = 0xc5c9e0 "2549619@hometest.voip.uio.no", len = 7}, blob_val = {s = 0xc5c9e0 "2549619@hometest.voip.uio.no", len = 7}, bitmap_val = 12962272}}, {type = DB1_STR, nul = 0, free = 10809332, val = {int_val = -1244124848, ll_val = 114719992144, double_val = 5.667920700952809e-313, time_val = -1244124848, string_val = 0xb5d82950 "sip:2549619@193.157.149.56", str_val = {s = 0xb5d82950 "sip:2549619@193.157.149.56", len = 26}, blob_val = {s = 0xb5d82950 "sip:2549619@193.157.149.56", len = 26}, bitmap_val = 3050842448}}, {type = DB1_DATETIME, nul = 0, free = 173661600, val = {int_val = 1345641342, ll_val = 1345641342, double_val = 6.6483515870591172e-315, time_val = 1345641342, string_val = 0x5034db7e <Address 0x5034db7e out of bounds>, str_val = {s = 0x5034db7e <Address 0x5034db7e out of bounds>, len = 0}, blob_val = {s = 0x5034db7e <Address 0x5034db7e out of bounds>, len = 0}, bitmap_val = 1345641342}}, {type = DB1_DOUBLE, nul = 0, free = 173661600, val = {int_val = 0, ll_val = -4616189618054758400, double_val = -1, time_val = 0, string_val = 0x0, str_val = {s = 0x0, len = -1074790400}, blob_val = {s = 0x0, len = -1074790400}, bitmap_val = 0}}, {type = DB1_STR, nul = 0, free = 140, val = {int_val = -1244124808, ll_val = 179144501624, double_val = 8.85091438937698e-313, time_val = -1244124808, string_val = 0xb5d82978 "ae372329-92b284e4-cb1aa8ab@193.157.149.56", str_val = {s = 0xb5d82978 "ae372329-92b284e4-cb1aa8ab@193.157.149.56", len = 41}, blob_val = { s = 0xb5d82978 "ae372329-92b284e4-cb1aa8ab@193.157.149.56", len = 41}, bitmap_val = 3050842488}}, {type = DB1_INT, nul = 0, free = 16594016, val = {int_val = 2, ll_val = 2, double_val = 9.8813129168249309e-324, time_val = 2, string_val = 0x2 <Address 0x2 out of bounds>, str_val = {s = 0x2 <Address 0x2 out of bounds>, len = 0}, blob_val = {s = 0x2 <Address 0x2 out of bounds>, len = 0}, bitmap_val = 2}}, {type = DB1_INT, nul = 0, free = 15, val = {int_val = 0, ll_val = 30064771072, double_val = 1.4853970536756906e-313, time_val = 0, string_val = 0x0, str_val = {s = 0x0, len = 7}, blob_val = {s = 0x0, len = 7}, bitmap_val = 0}}, {type = DB1_INT, nul = 0, free = 234, val = {int_val = 0, ll_val = 30923764531200, double_val = 1.5278369694949961e-310, time_val = 0, string_val = 0x0, str_val = {s = 0x0, len = 7200}, blob_val = {s = 0x0, len = 7200}, bitmap_val = 0}}, {type = DB1_STR, nul = 0, free = 20, val = {int_val = -1244124752, ll_val = 183439468976, double_val = 9.0631139712402749e-313, time_val = -1244124752, string_val = 0xb5d829b0 "PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054", str_val = {s = 0xb5d829b0 "PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054", len = 42}, blob_val = { s = 0xb5d829b0 "PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054", len = 42}, bitmap_val = 3050842544}}, {type = DB1_STR, nul = 1, free = -1210855736, val = {int_val = 16593448, ll_val = -5351701324369153496, double_val = -7.199759953567273e-50, time_val = 16593448, string_val = 0xfd3228 "\030\360\001", str_val = {s = 0xfd3228 "\030\360\001", len = -1246040064}, blob_val = {s = 0xfd3228 "\030\360\001", len = -1246040064}, bitmap_val = 16593448}}, {type = DB1_STR, nul = 1, free = 135809173, val = {int_val = 1915400, ll_val = 8226580360673800, double_val = 4.0644707389612159e-308, time_val = 1915400, string_val = 0x1d3a08 "\b\213E\b\211D$\004\213\203\\376\377\377\211\004$\350\262\361\373\377\203\304\024[]Í\266", str_val = { s = 0x1d3a08 "\b\213E\b\211D$\004\213\203\\376\377\377\211\004$\350\262\361\373\377\203\304\024[]Í\266", len = 1915400}, blob_val = {s = 0x1d3a08 "\b\213E\b\211D$\004\213\203\\376\377\377\211\004$\350\262\361\373\377\203\304\024[]Í\266", len = 1915400}, bitmap_val = 1915400}}, {type = DB1_STR, nul = 0, free = 3, val = {int_val = -1210919000, ll_val = 106163263400, double_val = 5.2451621296335371e-313, time_val = -1210919000, string_val = 0xb7d2d7a8 "udp:129.240.253.133:5060", str_val = {s = 0xb7d2d7a8 "udp:129.240.253.133:5060", len = 24}, blob_val = {s = 0xb7d2d7a8 "udp:129.240.253.133:5060", len = 24}, bitmap_val = 3084048296}}, {type = DB1_BITMAP, nul = 0, free = 20, val = {int_val = 8159, ll_val = 70920170733838303, double_val = 6.3704038403022417e-304, time_val = 8159, string_val = 0x1fdf <Address 0x1fdf out of bounds>, str_val = {s = 0x1fdf <Address 0x1fdf out of bounds>, len = 16512389}, blob_val = {s = 0x1fdf <Address 0x1fdf out of bounds>, len = 16512389}, bitmap_val = 8159}}, {type = DB1_DATETIME, nul = 0, free = -1, val = {int_val = 1345641222, ll_val = -4640175359789835514, double_val = -0.026157741446890113, time_val = 1345641222, string_val = 0x5034db06 <Address 0x5034db06 out of bounds>, str_val = {s = 0x5034db06 <Address 0x5034db06 out of bounds>, len = -1080375016}, blob_val = {s = 0x5034db06 <Address 0x5034db06 out of bounds>, len = -1080375016}, bitmap_val = 1345641222}}, {type = DB1_STR, nul = 0, free = 4094496, val = { int_val = -1244124696, ll_val = 88950188520, double_val = 4.3947232338834434e-313, time_val = -1244124696, string_val = 0xb5d829e8 "uloc-5034db04-67d5-1", str_val = {s = 0xb5d829e8 "uloc-5034db04-67d5-1", len = 20}, blob_val = { s = 0xb5d829e8 "uloc-5034db04-67d5-1", len = 20}, bitmap_val = 3050842600}}, {type = DB1_INT, nul = 1, free = -1244124968, val = {int_val = 26, ll_val = -5343475980977569766, double_val = -2.5829373687857378e-49, time_val = 26, string_val = 0x1a <Address 0x1a out of bounds>, str_val = {s = 0x1a <Address 0x1a out of bounds>, len = -1244124952}, blob_val = {s = 0x1a <Address 0x1a out of bounds>, len = -1244124952}, bitmap_val = 26}}, {type = DB1_INT, nul = 0, free = -1210856068, val = {int_val = 0, ll_val = 3530822193757814784, double_val = 1.1319814752747268e-72, time_val = 0, string_val = 0x0, str_val = {s = 0x0, len = 822083604}, blob_val = {s = 0x0, len = 822083604}, bitmap_val = 0}}, {type = DB1_STR, nul = 0, free = -1244124964, val = {int_val = 12962280, ll_val = 85912308200, double_val = 4.2446320036545221e-313, time_val = 12962280, string_val = 0xc5c9e8 "hometest.voip.uio.no", str_val = {s = 0xc5c9e8 "hometest.voip.uio.no", len = 20}, blob_val = {s = 0xc5c9e8 "hometest.voip.uio.no", len = 20}, bitmap_val = 12962280}}} nr_cols = <value optimized out> #2 0x00fcfc5d in insert_ucontact (_r=0xfd3a00, _contact=0xb7d3ce90, _ci=0xc5cc80, _c=0xbf9acb84) at urecord.c:478 No locals. #3 0x00c55bb0 in add_contacts (_m=0xb7d05e40, _d=0xb5d63060, _cflags=0, _uri=0x0) at save.c:493 res = <value optimized out> r = <value optimized out> u = 0xb7d3cc9c #4 save (_m=0xb7d05e40, _d=0xb5d63060, _cflags=0, _uri=0x0) at save.c:864 c = 0xb7d3ce88 st = <value optimized out> mode = <value optimized out> aor = {s = 0xc5c9e0 "2549619@hometest.voip.uio.no", len = 28} ret = <value optimized out> u = <value optimized out> #5 0x00c4dd43 in w_save2 (_m=0xb7d05e40, _d=0xb5d63060 "00ֵ", _cflags=0x0) at reg_mod.c:407 No locals. #6 0x080586ad in do_action (h=0xbf9acf48, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1157 ret = -5 v = <value optimized out> dst = {send_sock = 0x8, to = {s = {sa_family = 0, sa_data = "\000\000hΚ\277\025\225-\000x.\031\n"}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 3214593640}, sin_zero = "\025\225-\000x.\031\n"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 3214593640, sin6_addr = {in6_u = {u6_addr8 = "\025\225-\000x.\031\n\000\000\000\000\b\000\000", u6_addr16 = {38165, 45, 11896, 2585, 0, 0, 8, 0}, u6_addr32 = {2987285, 169422456, 0, 8}}}, sin6_scope_id = 174394728}}, id = 2987257, proto = 1 '\001', send_flags = {f = 0 '\000', blst_imask = 0 '\000'}} tmp = <value optimized out> new_uri = <value optimized out> end = <value optimized out> crt = <value optimized out> cmd = <value optimized out> len = <value optimized out> user = <value optimized out> uri = {user = {s = 0x1 <Address 0x1 out of bounds>, len = 174394568}, passwd = {s = 0x0, len = 10813760}, host = {s = 0xf <Address 0xf out of bounds>, len = 10813760}, port = {s = 0x961976 "\201\303~\326\016", len = 10813760}, params = {s = 0x0, len = -1080373724}, sip_params = {s = 0x0, len = 24}, headers = {s = 0x2d91be "\211ƅ\366u\326賯\377\377", <incomplete sequence \307>, len = 64768}, port_no = 0, proto = 0, type = ERROR_URI_T, flags = 294972, transport = { s = 0x81a4 <Address 0x81a4 out of bounds>, len = 1}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 2225}, method = {s = 0x0, len = 4096}, lr = {s = 0x10 <Address 0x10 out of bounds>, len = 0}, r2 = { s = 0x5034db04 <Address 0x5034db04 out of bounds>, len = 0}, gr = {s = 0x4e7c286b <Address 0x4e7c286b out of bounds>, len = 0}, transport_val = {s = 0x4e7c286b <Address 0x4e7c286b out of bounds>, len = 0}, ttl_val = { s = 0x4803c <Address 0x4803c out of bounds>, len = 0}, user_param_val = {s = 0xa201f9 "/etc/localtime", len = -1080373756}, maddr_val = {s = 0x964927 "\205\300\211\307tEe\203=\f", len = -1080373724}, method_val = { s = 0x962479 "\213]\364\213u\370\213}\374\211\354]Ë\223\314\025", len = 50}, lr_val = {s = 0xa4eff4 "\234M\025", len = 15}, r2_val = {s = 0xa201f9 "/etc/localtime", len = -1080373724}, gr_val = { s = 0x968b26 "\211\302\213]\364\211Ћu\370\213}\374\211\354]Ð\220\220\220\220\220\220\220\220U\211\345\203\354\030\211]\364\213E\f\350\217q\372\377\201ãd\016", len = 168882984}} next_hop = {user = {s = 0xbf9accf8 "", len = 2970786}, passwd = {s = 0xb7c074f4 "\004", len = -1080369992}, host = {s = 0xbf9accf8 "", len = 135239351}, port = {s = 0xbf9adcb8 "\003", len = -1212126312}, params = {s = 0xb7d05e40 "\001", len = 5289495}, sip_params = {s = 0x0, len = 1}, headers = {s = 0x4 <Address 0x4 out of bounds>, len = 173661209}, port_no = 52776, proto = 49050, type = 7504536, flags = 3214593272, transport = {s = 0x0, len = -1080369992}, ttl = {s = 0x0, len = -1080373848}, user_param = {s = 0x80604e1 "\213\225T\377\377\377\213\215X\377\377\377\200\346\376\211N\b\tډV\004\201\304\300", len = -1080374024}, maddr = {s = 0xb7c07eb0 "q\003", len = -1211081152}, method = {s = 0xbf9acf08 "@Ϛ\277\340\337\244", len = -1212123916}, lr = {s = 0xb7c074f0 "\001", len = 0}, r2 = {s = 0xbf9acd10 "$Κ\277\240җ", len = 10809332}, gr = {s = 0xbf9acd80 "", len = 10201187}, transport_val = {s = 0xa4eff4 "\234M\025", len = -1080373724}, ttl_val = { s = 0x97d2a0 "\205\300\017\204\033\001", len = 3}, user_param_val = {s = 0xa201f9 "/etc/localtime", len = -1080373888}, maddr_val = {s = 0xbf9acea4 "@^з(Ϛ\277\\376\005\bHϚ\277\300\005ķ@^з", len = 9836918}, method_val = { s = 0x2df578 "\210", <incomplete sequence \324>, len = 4}, lr_val = {s = 0x728195 "x}", len = 9836918}, r2_val = {s = 0x2d5bb0 "\203\370\377\211\306\017\204i\373\377\377\213M\b\203\307\001\213A\030\003E\354\211A\030\017\266", len = 174394568}, gr_val = {s = 0xa4f7240 "\020", len = 1}} u = <value optimized out> port = <value optimized out> i = <value optimized out> flags = <value optimized out> avp = <value optimized out> st = {flags = 3214593656, id = 5725, name = {n = 10617337, s = {s = 0xa201f9 "/etc/localtime", len = 3232052}, re = 0xa201f9}, avp = 0xf} sct = <value optimized out> sjt = <value optimized out> rve = <value optimized out> mct = <value optimized out> rv = <value optimized out> rv1 = <value optimized out> c1 = {cache_type = 10617337, val_type = 9949531, c = {avp_val = {n = 10809332, s = {s = 0xa4eff4 "\234M\025", len = 1}, re = 0xa4eff4}, pval = {rs = {s = 0xa4eff4 "\234M\025", len = 1}, ri = 168882984, flags = -1080373616}}, i2s = "\342\302\227\000\371\001\242\000\000\000\000\000\000\000\000\000\371\001\242\000\234", <incomplete sequence \316>} s = {s = 0xa4eff4 "\234M\025", len = 10613054} srevp = {0xa50140, 0x97c1fd} mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, { type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}} #7 0x0805fe5c in run_actions (h=0xbf9acf48, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1644 t = 0xb7c405c0 ret = <value optimized out> mod = <value optimized out> ms = 0 #8 0x080604e1 in run_actions_safe (h=0xbf9adcb8, a=0xb7c405c0, msg=0xb7d05e40) at action.c:1708 ctx = {rec_lev = 1, run_flags = 0, last_retcode = 0, jmp_env = {{__jmpbuf = {0, -1080369992, 0, -1080373464, -1167974323, 234811079}, __mask_was_saved = 0, __saved_mask = {__val = {174331556, 10813760, 3214593944, 10813796, 10813796, 173661228, 10813808, 10617337, 1, 10813760, 174339728, 13656, 10624544, 0, 842274453, 10809332, 174331548, 10613054, 3214594260, 9969796, 174331548, 8180, 10613054, 3214594308, 10806304, 3214594120, 10814568, 8216, 10809332, 8016, 174331528, 3214594116}}}}} ret = 0 #9 0x080f96b7 in rval_get_int (h=0xbf9adcb8, msg=0xbf9ac954, i=0xbf9ad268, rv=0xb7c406cc, cache=0x0) at rvalue.c:920 r_avp = <value optimized out> avp_val = {n = -1212330376, s = {s = 0xb7bd4e78 "", len = 0}, re = 0xb7bd4e78} pval = {rs = {s = 0xb7bd4e78 "", len = -1211081152}, ri = 26, flags = -1080372456} tmp = { s = 0x80586ad "\213}\b1҅\300\211E\360\017\224\302\tW\004\211G\b\243\300V&\b\351~\374\377\377\213]\f\213}\020\213K<\213S\030\211L$\b\213s0\211<$\211t$\004\353ċ]\f\213E\020\213SH\213s\030\211T$\f\213{<\211|$\b\213K0\211\004$\211L$\004\377V\004롋]\f\213CT\213s\030\211D$\020\213SH\213E\020\211T$\f\213{<\211|$\b\213K0\211\004$\211L$\004\377V\004\351q\377\377\377\213]\f\213{`\213s\030\211|$\024\213KT\211L$\020\213CH\213M\020\211D$\f\213S<\211T$\b\213{0\211\f$\211|$\004\377V\004\351:\377\377\377\213M"..., len = -1211081152} s = <value optimized out> r = <value optimized out> ret = <value optimized out> destroy_pval = <value optimized out> #10 0x080fcf38 in rval_expr_eval_int (h=0xbf9adcb8, msg=0xb7d05e40, res=0xbf9ad268, rve=0xb7c406c8) at rvalue.c:1914 i1 = <value optimized out> i2 = <value optimized out> ret = <value optimized out> c1 = {cache_type = 21, val_type = RV_NONE, c = {avp_val = {n = 42, s = {s = 0x2a <Address 0x2a out of bounds>, len = 13}, re = 0x2a}, pval = {rs = {s = 0x2a <Address 0x2a out of bounds>, len = 13}, ri = 15, flags = 22}}, i2s = "\a\000\000\000p\000\000\000\003\000\000\000\352\000\000\000\001\000\000\000 \034"} c2 = {cache_type = 21, val_type = 173661376, c = {avp_val = {n = -1080372852, s = {s = 0xbf9ad18c "\250њ\277zx\234", len = 10253525}, re = 0xbf9ad18c}, pval = {rs = {s = 0xbf9ad18c "\250њ\277zx\234", len = 10253525}, ri = 174331536, flags = 174331536}}, i2s = "\254\000\000\000\000@\000\000 \344\244\000\070rO\nXњ\277\030", <incomplete sequence \321>} rv1 = <value optimized out> rv2 = <value optimized out> #11 0x080fd009 in rval_expr_eval_int (h=0xbf9adcb8, msg=0xb7d05e40, res=0xbf9ad544, rve=0xb7c40a70) at rvalue.c:1922 i1 = <value optimized out> i2 = <value optimized out> ret = <value optimized out> c1 = {cache_type = 134610524, val_type = RV_NONE, c = {avp_val = {n = 0, s = {s = 0x0, len = 2}, re = 0x0}, pval = {rs = {s = 0x0, len = 2}, ri = 131072, flags = 137121601}}, i2s = "\030\b(\b\000\000\000\000\371\001\242\000PҚ\277 a1\000\b"} c2 = {cache_type = 3211677, val_type = 172978744, c = {avp_val = {n = 1, s = {s = 0x1 <Address 0x1 out of bounds>, len = -1080372644}, re = 0x1}, pval = {rs = {s = 0x1 <Address 0x1 out of bounds>, len = -1080372644}, ri = -1212121552, flags = 1}}, i2s = "@^з\377\377\377\377\300\035\301\267\000\000\000\000\000\000\304\023\003"} rv1 = <value optimized out> rv2 = <value optimized out> #12 0x080585fe in do_action (h=0xbf9adcb8, a=0xb7c41550, msg=0xb7d05e40) at action.c:1121 ret = -5 v = <value optimized out> dst = {send_sock = 0x0, to = {s = {sa_family = 0, sa_data = "\000\000\000\000\000\000\000\000\000\000\377\377\377\377"}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\377\377\377\377"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {in6_u = {u6_addr8 = "\000\000\000\000\377\377\377\377\365\311÷\v\000\000", u6_addr16 = {0, 0, 65535, 65535, 51701, 47043, 11, 0}, u6_addr32 = {0, 4294967295, 3083061749, 11}}}, sin6_scope_id = 0}}, id = 0, proto = -99 '\235', send_flags = {f = 58 ':', blst_imask = 1 '\001'}} tmp = <value optimized out> new_uri = <value optimized out> end = <value optimized out> crt = <value optimized out> cmd = <value optimized out> len = <value optimized out> user = <value optimized out> uri = {user = {s = 0x15 <Address 0x15 out of bounds>, len = -1246040064}, passwd = {s = 0x1d38d8 "\a", len = -1080372168}, host = { s = 0x8184895 "\213E\360\203\304\034[^_\311ËU\b\215F\b\215Y\370\211>\001ljE\360\211\037\213B\b\203\300\b\211B\b\211D$\004\307\004$\006", len = 1915096}, port = {s = 0x1d38d8 "\a", len = 16384}, params = {s = 0xa4e420 "", len = 5}, sip_params = { s = 0xb5baf010 "\270\061\273\265\370ﺷ", len = -1244125016}, headers = {s = 0x0, len = 36}, port_no = 273, proto = 0, type = 3214595224, flags = 135776296, transport = {s = 0xb5baf000 "", len = 36}, ttl = { s = 0xffffffff <Address 0xffffffff out of bounds>, len = -1212370000}, user_param = {s = 0xb7baf008 "", len = 1630016}, maddr = {s = 0xbf9ad488 "\v", len = 0}, method = {s = 0xb7c40224 "\004", len = -1080369992}, lr = { s = 0xbf9ad4c8 "\330՚\277\070\317\017\b\270ܚ\277@^з\244\330\232\277$\002ķ", len = 135239351}, r2 = {s = 0xbf9adcb8 "\003", len = -1211891792}, gr = {s = 0xb7d05e40 "\001", len = -1244125004}, transport_val = {s = 0xbf9adcb8 "\003", len = -1080371552}, ttl_val = {s = 0xb <Address 0xb out of bounds>, len = 137187132}, user_param_val = {s = 0x111 <Address 0x111 out of bounds>, len = -1211905547}, maddr_val = { s = 0xbf9ad4c8 "\330՚\277\070\317\017\b\270ܚ\277@^з\244\330\232\277$\002ķ", len = 135778466}, method_val = {s = 0x111 <Address 0x111 out of bounds>, len = -1211905547}, lr_val = {s = 0xb <Address 0xb out of bounds>, len = 0}, r2_val = {s = 0x0, len = 135}, gr_val = {s = 0xb7d3d0a0 "\002", len = -1080371036}} next_hop = {user = {s = 0x2 <Address 0x2 out of bounds>, len = 160}, passwd = {s = 0xa641688 "", len = 9836918}, host = { s = 0xa50170 "\020Sn\n\020\337Y\n\210\026d\n\230\335Y\nh\016e\n0rO\n\240\re\nP\333Y\n\340\343\026\nPj\027\n\030hO\n\030hO\n\230\001\245", len = 0}, port = {s = 0xb7c121d4 "\004", len = -1080369992}, params = {s = 0xbf9ad3b8 "", len = 135239351}, sip_params = {s = 0xbf9adcb8 "\003", len = -1212080704}, headers = {s = 0xb7d05e40 "\001", len = 5289495}, port_no = 0, proto = 0, type = 10813760, flags = 174331688, transport = {s = 0x54c0 <Address 0x54c0 out of bounds>, len = 10624544}, ttl = { s = 0x1 <Address 0x1 out of bounds>, len = 8}, user_param = {s = 0x0, len = -1080369992}, maddr = {s = 0x0, len = -1080372120}, method = {s = 0x80604e1 "\213\225T\377\377\377\213\215X\377\377\377\200\346\376\211N\b\tډV\004\201\304\300", len = -1080372296}, lr = {s = 0xb7c3ffb0 "\177\004", len = -1211081152}, r2 = {s = 0xbf9ad5c8 "", len = -1212079660}, gr = {s = 0xb7c121d0 "\001", len = 0}, transport_val = {s = 0x0, len = 1}, ttl_val = {s = 0x0, len = -1080369992}, user_param_val = { s = 0x0, len = -1080372328}, maddr_val = {s = 0xba623ddd <Address 0xba623ddd out of bounds>, len = 234811079}, method_val = {s = 0x0, len = 173660872}, lr_val = {s = 0xbf9ad404 "\330\070\035", len = -1080372216}, r2_val = { s = 0xa60ef2 "\211F\f1\300뽍\264&", len = -1212485624}, gr_val = {s = 0x0, len = 10809332}} u = <value optimized out> port = <value optimized out> i = <value optimized out> flags = <value optimized out> avp = <value optimized out> st = {flags = 4932939, id = 54696, name = {n = -1211904900, s = {s = 0xb7c3cc7c "\001", len = 0}, re = 0xb7c3cc7c}, avp = 0xbf9ad5d8} sct = <value optimized out> sjt = <value optimized out> rve = 0xb7c40a70 mct = <value optimized out> rv = <value optimized out> rv1 = <value optimized out> c1 = {cache_type = 3083076132, val_type = 3083076128, c = {avp_val = {n = -1080371752, s = {s = 0xbf9ad5d8 "\270\330\232\277W\206\005\b\270ܚ\277P\025ķ@^з \002ķ\004\333\064P", len = 135253816}, re = 0xbf9ad5d8}, pval = {rs = { s = 0xbf9ad5d8 "\270\330\232\277W\206\005\b\270ܚ\277P\025ķ@^з \002ķ\004\333\064P", len = 135253816}, ri = -1080369992, flags = -1211081152}}, i2s = "\244\330\232\277$\002ķ\000\000\000\000\260\263\274\267@^з\362", <incomplete sequence \344>} s = {s = 0xb7c3cac0 "", len = 254} srevp = {0x80aaeec, 0xb7c3cc7c} mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, { type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}} #13 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7c41550, msg=0xb7d05e40) at action.c:1644 t = 0xb7c41550 ret = <value optimized out> mod = <value optimized out> ms = 0 #14 0x08058657 in do_action (h=0xbf9adcb8, a=0xb7c41650, msg=0xb7d05e40) at action.c:1136 ret = 1 v = 1 dst = {send_sock = 0x0, to = {s = {sa_family = 320, sa_data = "\245\000\070\334Y\n\017\000\000\000@\001\245"}, sin = {sin_family = 320, sin_port = 165, sin_addr = {s_addr = 173661240}, sin_zero = "\017\000\000\000@\001\245"}, sin6 = {sin6_family = 320, sin6_port = 165, sin6_flowinfo = 173661240, sin6_addr = {in6_u = {u6_addr8 = "\017\000\000\000@\001\245\000v\031\226\000!Ε", u6_addr16 = {15, 0, 320, 165, 6518, 150, 52769, 149}, u6_addr32 = {15, 10813760, 9836918, 9817633}}}, sin6_scope_id = 10813760}}, id = 0, proto = 64 '@', send_flags = {f = 1 '\001', blst_imask = 165 '\245'}} tmp = <value optimized out> new_uri = <value optimized out> end = <value optimized out> crt = <value optimized out> cmd = <value optimized out> len = <value optimized out> user = <value optimized out> uri = {user = {s = 0x0, len = 9949531}, passwd = {s = 0x1 <Address 0x1 out of bounds>, len = 24}, host = {s = 0x0, len = -1080371236}, port = {s = 0xb7d3d098 "\030\002", len = 10617337}, params = {s = 0x0, len = -1210855256}, sip_params = { s = 0xb7baf008 "", len = -1080371256}, headers = {s = 0x80fbc28 "\213]\364\213u\370\213}\374\311Ë\035\370]&\b\205\333\017\205*\377\377\377\241\370]&\b\213\065$\330&\b@\205\366\243\370]&\b\017\205k\001", len = -1212485624}, port_no = 53408, proto = 47059, type = 10616677, flags = 3214597412, transport = {s = 0xa6416a4 " /nett/kamailio/current/sbin/kamailio[26581]: DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (7/0)\n", len = 0}, ttl = { s = 0x9ba863 "\207Ӊ\302\201", <incomplete sequence \372>, len = 10813796}, user_param = {s = 0x4e18e0 "193.157.149.56", len = 14}, maddr = { s = 0xa50170 "\020Sn\n\020\337Y\n\210\026d\n\230\335Y\nh\016e\n0rO\n\240\re\nP\333Y\n\340\343\026\nPj\027\n\030hO\n\030hO\n\230\001\245", len = 0}, method = {s = 0xb7bd578c "\004", len = -1080369992}, lr = { s = 0xbf9ad828 "8\331\232\277\070\317\017\b\270ܚ\277@^з\004ܚ\277\214W\275\267", len = 135239351}, r2 = {s = 0xbf9adcb8 "\003", len = -1212328320}, gr = {s = 0xb7d05e40 "\001", len = -1212373388}, transport_val = {s = 0x0, len = 0}, ttl_val = { s = 0xbf9adca8 "@^з ", <incomplete sequence \344\244>, len = -1}, user_param_val = {s = 0xb7bca674 "\002", len = -1080370172}, maddr_val = {s = 0xb7d3d0a0 "\002", len = -1080371184}, method_val = {s = 0xbf9add80 "i\362=\377", len = -1080371072}, lr_val = {s = 0x9ba863 "\207Ӊ\302\201", <incomplete sequence \372>, len = -1212366860}, r2_val = {s = 0xb7bcbbdc "\a", len = 9949856}, gr_val = {s = 0x0, len = -1080370172}} next_hop = {user = {s = 0x2 <Address 0x2 out of bounds>, len = 0}, passwd = {s = 0x4e18e0 "193.157.149.56", len = 14}, host = {s = 0xe <Address 0xe out of bounds>, len = 0}, port = {s = 0xb7d3d0a8 "V\322\323\267\016", len = 0}, params = { s = 0xbf9ad718 "", len = 135249768}, sip_params = {s = 0xb7bcbff4 "\002", len = -1211081152}, headers = {s = 0x2 <Address 0x2 out of bounds>, len = -1212366860}, port_no = 0, proto = 0, type = 10618599, flags = 10618598, transport = {s = 0x0, len = -1212366860}, ttl = {s = 0xbf9ad924 "\001", len = -1210855264}, user_param = {s = 0x0, len = -1080369992}, maddr = {s = 0x0, len = -1080371256}, method = { s = 0x80604e1 "\213\225T\377\377\377\213\215X\377\377\377\200\346\376\211N\b\tډV\004\201\304\300", len = -1080371432}, lr = {s = 0xb7bd5680 "\002\002", len = -1211081152}, r2 = {s = 0x0, len = -1080371268}, gr = {s = 0x2 <Address 0x2 out of bounds>, len = 0}, transport_val = {s = 0x0, len = -1}, ttl_val = {s = 0x0, len = -1080369992}, user_param_val = {s = 0x0, len = -1080371464}, maddr_val = {s = 0xba62387d <Address 0xba62387d out of bounds>, len = 234811079}, method_val = {s = 0x0, len = 536}, lr_val = {s = 0xb7d3d0a0 "\002", len = -1080371320}, r2_val = {s = 0x8184b77 "\241\004 &\b\213\230\260", len = 1629480}, gr_val = {s = 0x18dd28 "D$\b\213\203\304\376\377\377\211D$\004\377\223\300\376\377\377\205\300\017\204\264\002", len = 2}} u = <value optimized out> port = <value optimized out> i = <value optimized out> flags = <value optimized out> avp = <value optimized out> st = {flags = 24, id = 21712, name = {n = 64768, s = {s = 0xfd00 <Address 0xfd00 out of bounds>, len = 0}, re = 0xfd00}, avp = 0x0} sct = <value optimized out> sjt = <value optimized out> rve = 0xb7c40220 mct = <value optimized out> rv = <value optimized out> rv1 = <value optimized out> c1 = {cache_type = 3082639244, val_type = 3082639240, c = {avp_val = {n = -1080370888, s = {s = 0xbf9ad938 "\030ܚ\277=\205\005\b\270ܚ\277P\026ķ@^з\210W\275\267\244\201", len = 135253816}, re = 0xbf9ad938}, pval = {rs = { s = 0xbf9ad938 "\030ܚ\277=\205\005\b\270ܚ\277P\026ķ@^з\210W\275\267\244\201", len = 135253816}, ri = -1080369992, flags = -1211081152}}, i2s = "\004ܚ\277\214W\275\267\000\000\000\000\314\330\232\277\001\000\000\000\b "} s = {s = 0x1 <Address 0x1 out of bounds>, len = 0} srevp = {0x4803c, 0x81a4} mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, { type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}} #15 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7c41650, msg=0xb7d05e40) at action.c:1644 t = 0xb7c41650 ret = <value optimized out> mod = <value optimized out> ms = 0 #16 0x0805853d in do_action (h=0xbf9adcb8, a=0xb7bd64d8, msg=0xb7d05e40) at action.c:761 ret = -5 v = <value optimized out> dst = {send_sock = 0x96429f, to = {s = {sa_family = 65535, sa_data = "\377\377\300o\201\000\254\257\004\bpv\201"}, sin = {sin_family = 65535, sin_port = 65535, sin_addr = {s_addr = 8482752}, sin_zero = "\254\257\004\bpv\201"}, sin6 = {sin6_family = 65535, sin6_port = 65535, sin6_flowinfo = 8482752, sin6_addr = {in6_u = {u6_addr8 = "\254\257\004\bpv\201\000\000ܚ\277H\216\200", u6_addr16 = {44972, 2052, 30320, 129, 56320, 49050, 36424, 128}, u6_addr32 = {134524844, 8484464, 3214597120, 8425032}}}, sin6_scope_id = 8484904}}, id = -1208280984, proto = 1 '\001', send_flags = {f = 0 '\000', blst_imask = 0 '\000'}} tmp = <value optimized out> new_uri = <value optimized out> end = <value optimized out> crt = <value optimized out> cmd = <value optimized out> len = <value optimized out> user = <value optimized out> uri = {user = {s = 0x1 <Address 0x1 out of bounds>, len = 8482752}, passwd = {s = 0x817828 "\314w\201", len = -1080370264}, host = {s = 0xbf9adbc4 "", len = 8407671}, port = {s = 0x804afac "\243\002", len = -1080370264}, params = { s = 0x8177cc "0\030\373\267\005", len = 3}, sip_params = {s = 0xb7fb1868 "\313`\005\b\020ii\r", len = 1}, headers = {s = 0x0, len = 1}, port_no = 65535, proto = 65535, type = ERROR_URI_T, flags = 168882984, transport = { s = 0xbf9adb6c "\364", <incomplete sequence \357\244>, len = 9945826}, ttl = {s = 0xa201f9 "/etc/localtime", len = 0}, user_param = {s = 0x0, len = -1080370252}, maddr = { s = 0xa50170 "\020Sn\n\020\337Y\n\210\026d\n\230\335Y\nh\016e\n0rO\n\240\re\nP\333Y\n\340\343\026\nPj\027\n\030hO\n\030hO\n\230\001\245", len = 8200}, method = {s = 0x2 <Address 0x2 out of bounds>, len = 9836918}, lr = { s = 0xa1ff65 "corrupted double-linked list", len = 3520}, r2 = {s = 0xa6416a4 " /nett/kamailio/current/sbin/kamailio[26581]: DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (7/0)\n", len = 10813760}, gr = { s = 0xbf9adbf0 "$\032\220", len = 8484464}, transport_val = {s = 0x8050d9f "_setjmp", len = 10813760}, ttl_val = {s = 0xa50170 "\020Sn\n\020\337Y\n\210\026d\n\230\335Y\nh\016e\n0rO\n\240\re\nP\333Y\n\340\343\026\nPj\027\n\030hO\n\030hO\n\230\001\245", len = 10617337}, user_param_val = {s = 0xa8428197 <Address 0xa8428197 out of bounds>, len = 0}, maddr_val = {s = 0x0, len = 13656}, method_val = {s = 0xa21e20 "free(): corrupted unsorted chunks", len = 0}, lr_val = { s = 0x32341695 <Address 0x32341695 out of bounds>, len = 10809332}, r2_val = {s = 0xa64169c "", len = 10613054}, gr_val = {s = 0xbf9adc94 "(q\274\267h\335\232\277d\004\006\b\270ܚ\277(q\274\267@^з ", <incomplete sequence \344\244>, len = 9969796}} next_hop = {user = {s = 0xa201f9 "/etc/localtime", len = -1080370596}, passwd = {s = 0xbf9ada20 "", len = 0}, host = {s = 0xbf9ada40 "\f\025\373\267\300o\201", len = 10805216}, port = {s = 0x3 <Address 0x3 out of bounds>, len = 168883016}, params = { s = 0x8 <Address 0x8 out of bounds>, len = 10613062}, sip_params = {s = 0x0, len = 8406405}, headers = {s = 0x90bcd0 "GLIBC_2.0", len = 134570187}, port_no = 6248, proto = 47099, type = 4294901762, flags = 8428425, transport = { s = 0x8050b70 "libc.so.6", len = -1208281844}, ttl = {s = 0x816fc0 "\370\276\001", len = -1208281028}, user_param = {s = 0xbf9ada98 "", len = -1080370484}, maddr = {s = 0x80495d "\205\300t\275\351=\376\377\377\215v", len = 10809332}, method = { s = 0xbf9adb78 "\224ܚ\277\204 \230", len = 9973573}, lr = {s = 0xa6416a2 "42 /nett/kamailio/current/sbin/kamailio[26581]: DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (7/0)\n", len = -1208281784}, r2 = { s = 0x8fa1a4 "\240\060\020D", len = 1}, gr = {s = 0x0, len = -1080370536}, transport_val = {s = 0xbf9adbb4 "\377\377\377\377\300o\201", len = -1472036457}, ttl_val = {s = 0x5 <Address 0x5 out of bounds>, len = 9428004}, user_param_val = { s = 0x8fc8c8 "\226\201B\250\017\204\035\346|`\234|\374Qcq\zy\360\003\346`\033|\231/\310Km\301\243\353\372\266=/\222\210\353", <incomplete sequence \352>, len = -1472036458}, maddr_val = {s = 0x10 <Address 0x10 out of bounds>, len = 0}, method_val = { s = 0x0, len = 1}, lr_val = {s = 0x3e0 <Address 0x3e0 out of bounds>, len = -1208280984}, r2_val = {s = 0xb7fb1548 "", len = 134548895}, gr_val = {s = 0x906794 "", len = 134524844}} u = <value optimized out> port = <value optimized out> i = 12 flags = <value optimized out> avp = <value optimized out> st = {flags = 1, id = 0, name = {n = 134548895, s = {s = 0x8050d9f "_setjmp", len = 0}, re = 0x8050d9f}, avp = 0x8261a74} sct = <value optimized out> sjt = <value optimized out> rve = <value optimized out> mct = <value optimized out> rv = 0xb7bc7128 rv1 = <value optimized out> c1 = {cache_type = 174331548, val_type = 8180, c = {avp_val = {n = 10613054, s = {s = 0xa1f13e "%H:%M:%S", len = -1080369980}, re = 0xa1f13e}, pval = {rs = {s = 0xa1f13e "%H:%M:%S", len = -1080369980}, ri = 10806304, flags = 174331528}}, i2s = "p\004\245\000\030 \000\000\364\357\244\000x\037\000\000$\032\220\000H\025"} s = {s = 0xbf9adcb8 "\003", len = 0} srevp = {0x1, 0x901a24} mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, { type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}} #17 0x0805fe5c in run_actions (h=0xbf9adcb8, a=0xb7bc7128, msg=0xb7d05e40) at action.c:1644 t = 0xb7bd64d8 ret = <value optimized out> mod = <value optimized out> ms = 0 #18 0x08060464 in run_top_route (a=0xb7bc7128, msg=0xb7d05e40, c=0x0) at action.c:1729 ctx = {rec_lev = 3, run_flags = 0, last_retcode = 1, jmp_env = {{__jmpbuf = {-1080369992, 0, -1212387032, -1080370024, -1167969571, 234811079}, __mask_was_saved = 0, __saved_mask = {__val = {234, 1, 7200, 168883016, 10254458, 135, 4294967295, 12443959, 3050814344, 135, 3214597480, 135828890, 3083886144, 2, 0, 0, 7, 4532726, 3214597432, 4482608, 4809436, 4403718, 3214597448, 4591547, 0, 3084056472, 3214597480, 135297783, 3083886144, 1073741825, 0, 3083886144}}}}} p = 0xbf9adcb8 ret = <value optimized out> sfbk = 0 #19 0x080e11e4 in receive_msg (buf=0x82c4f20 "REGISTER sip:hometest.voip.uio.no SIP/2.0\r\nVia: SIP/2.0/UDP 193.157.149.56;branch=z9hG4bKb8e88f2eE34DCDDD\r\nFrom: "kolbutest" sip:2549619@hometest.voip.uio.no;tag=34CE9BA6-70FCC135\r\nTo: <sip:2549619@"..., len=809, rcv_info=0xbf9ade98) at receive.c:209 msg = <value optimized out> ctx = {rec_lev = 173660872, run_flags = 0, last_retcode = 0, jmp_env = {{__jmpbuf = {10809332, 21, 173660872, 10809332, 169272288, 10813760}, __mask_was_saved = -1080369688, __saved_mask = {__val = {9839737, 16384, 10806304, 0, 10809332, 169306704, 10813760, 3214597640, 9839737, 9448916, 3086685512, 169306712, 4294967295, 8482752, 134526028, 8484464, 3214597680, 8425032, 8484904, 3086686312, 1, 1, 0, 134549081, 0, 136715172, 1, 9448916, 10, 3083908104, 3214597892, 3214597912}}}}} ret = <value optimized out> inb = {s = 0x82c4f20 "REGISTER sip:hometest.voip.uio.no SIP/2.0\r\nVia: SIP/2.0/UDP 193.157.149.56;branch=z9hG4bKb8e88f2eE34DCDDD\r\nFrom: "kolbutest" sip:2549619@hometest.voip.uio.no;tag=34CE9BA6-70FCC135\r\nTo: <sip:2549619@"..., len = 809} #20 0x08177f7b in udp_rcv_loop () at udp_server.c:544 len = 809 tmp = <value optimized out> fromlen = 16 ri = {src_ip = {af = 2, len = 4, u = {addrl = {949329345, 3214597816, 9595014, 1575301381}, addr32 = {949329345, 3214597816, 9595014, 1575301381}, addr16 = {40385, 14485, 57016, 49050, 26758, 146, 12549, 24037}, addr = "\301\235\225\070\270ޚ\277\206h\222\000\005\061\345]"}}, dst_ip = {af = 2, len = 4, u = {addrl = {2248011905, 0, 0, 0}, addr32 = {2248011905, 0, 0, 0}, addr16 = {61569, 34301, 0, 0, 0, 0, 0, 0}, addr = "\201\360\375\205", '\000' <repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023\304\301\235\225\070\000\000\000\000\000\000\000"}, sin = { sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 949329345}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 949329345, sin6_addr = {in6_u = {u6_addr8 = '\000' <repeats 15 times>, u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, bind_address = 0xb7d2d8e8, proto = 1 '\001'} buf = "REGISTER sip:hometest.voip.uio.no SIP/2.0\r\nVia: SIP/2.0/UDP 193.157.149.56;branch=z9hG4bKb8e88f2eE34DCDDD\r\nFrom: "kolbutest" sip:2549619@hometest.voip.uio.no;tag=34CE9BA6-70FCC135\r\nTo: <sip:2549619@"... #21 0x080b0426 in main_loop () at main.c:1633 i = 2 pid = 0 si = 0xb7d2d8e8 si_desc = "udp receiver child=2 sock=129.240.253.133:5060\000\277\225H\030\b\b\237\034\000\b\237\034\000\377\377\377\377\260\250 \b\001\000\000\000P\360\272\265`-ֵp\351\026\npIз\002\000\000\000p\351\026\n\004\333\064P\001\000\000\000\000\000\000\000\032\000\000\000\002", '\000' <repeats 11 times>"\350, \337\232\277" nrprocs = 6 #22 0x080b3d02 in main (argc=17, argv=0xbf9ae174) at main.c:2546 cfg_stream = 0xa109008 c = <value optimized out> r = 0 tmp = 0xbf9ae1bc "\f\377\232\277.\377\232\277\071\377\232\277L\377\232\277o\377\232\277u\377\232\277\206\377\232\277\250\377\232\277\260\377\232\277" tmp_len = 9592645 port = 136337865 proto = -1080368920 ret = <value optimized out> seed = 1746956911 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x0 p = 0x0
Also, can you give it a quick try with 9p instead of 7p for both connections?
9p for both works! At least not crashes.
Changed to:
modparam("db_cluster", "cluster", "data2=>voip2_data2=9s9p;voip1_data2=9s9p") modparam("usrloc", "db_mode", 3)
But it only writes to one of the databases. In this case the one defined in voip1_data2. Have you tried db_cluster together with the registrar-module? I'd like all writing to go to both databases, but reading should be failover-based.
Hello,
On 8/22/12 6:34 PM, Øyvind Kolbu wrote:
On 2012-08-22 at 16:01, Daniel-Constantin Mierla wrote:
Hello,
can you send the output of 'bt full' from gdb?
#0 0x002fd7da in db_cluster_insert (_h=0xb7d2dc88, _k=0xbf9ac954, _v=0xbf9ac7ec, _n=18) at dbcl_api.c:334
I will look over it when I get the first chance.
[...]
Also, can you give it a quick try with 9p instead of 7p for both connections?
9p for both works! At least not crashes.
Changed to:
modparam("db_cluster", "cluster", "data2=>voip2_data2=9s9p;voip1_data2=9s9p") modparam("usrloc", "db_mode", 3)
But it only writes to one of the databases. In this case the one defined in voip1_data2. Have you tried db_cluster together with the registrar-module? I'd like all writing to go to both databases, but reading should be failover-based.
I looked I my config used for testing during development and I have an use case with 9p/9p for two connections for write, tested with acc module.
Cheers, Daniel
Hello,
can you print the content of cls in frame 0 inside gdb?
p *cls
I found and fixed a potential issue, by now in master:
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=4d15ba97...
You can cherry pick it in branch 3.3 and try it, with:
git pull origin git cherry-pick -x 4d15ba97bab58108cfedc45158d90583f67cdadf
But first get the content of cls, the fix I did was not convincing me it is the reason for what you reported.
Cheers, Daniel
On 8/23/12 9:29 AM, Daniel-Constantin Mierla wrote:
Hello,
On 8/22/12 6:34 PM, Øyvind Kolbu wrote:
On 2012-08-22 at 16:01, Daniel-Constantin Mierla wrote:
Hello,
can you send the output of 'bt full' from gdb?
#0 0x002fd7da in db_cluster_insert (_h=0xb7d2dc88, _k=0xbf9ac954, _v=0xbf9ac7ec, _n=18) at dbcl_api.c:334
I will look over it when I get the first chance.
[...]
Also, can you give it a quick try with 9p instead of 7p for both connections?
9p for both works! At least not crashes.
Changed to:
modparam("db_cluster", "cluster",
"data2=>voip2_data2=9s9p;voip1_data2=9s9p") modparam("usrloc", "db_mode", 3)
But it only writes to one of the databases. In this case the one defined in voip1_data2. Have you tried db_cluster together with the registrar-module? I'd like all writing to go to both databases, but reading should be failover-based.
I looked I my config used for testing during development and I have an use case with 9p/9p for two connections for write, tested with acc module.
Cheers, Daniel
On 2012-08-24 at 09:22, Daniel-Constantin Mierla wrote:
Hello,
can you print the content of cls in frame 0 inside gdb?
p *cls
(gdb) p *cls $1 = {name = {s = 0xb7b5a958 "data2=>voip2_data2=8r9p", len = 5}, clsid = 1761460487, ref = 1, rlist = {{clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0xb7b5a7c8, 0x0, 0x0, 0x0, 0x0}, clen = 1, prio = 8, mode = 114, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}}, wlist = { {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, { clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, { clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0x0, 0x0, 0x0, 0x0, 0x0}, clen = 0, prio = 0, mode = 0, crt = 0}, {clist = {0xb7b5a7c8, 0x0, 0x0, 0x0, 0x0}, clen = 1, prio = 9, mode = 112, crt = 0}}, usedcon = 0xb7b5a7c8, next = 0x0}
I found and fixed a potential issue, by now in master:
http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=4d15ba97...
You can cherry pick it in branch 3.3 and try it, with:
git pull origin git cherry-pick -x 4d15ba97bab58108cfedc45158d90583f67cdadf
But first get the content of cls, the fix I did was not convincing me it is the reason for what you reported.
First impression is that everything is working now, thanks! At least registrations are getting populated in both databases from both servers. As I'm out traveling I havn't yet tested calling and whether or not the failover works as expected. I assume setting usrloc's db_mode to 3 is recommended in this kind of setup?
For now I'm using: modparam("db_cluster", "cluster","data2=>voip1_data2=9s9p;voip2_data2=8s9p") on my voip1 machine, and the line below on the voip2 machine: modparam("db_cluster", "cluster","data2=>voip2_data2=9s9p;voip1_data2=8s9p")
The same configuration created coredumps on both machines previously.
On 2012-08-24 at 10:48, Øyvind Kolbu wrote:
First impression is that everything is working now, thanks! At least registrations are getting populated in both databases from both servers. As I'm out traveling I havn't yet tested calling and whether or not the failover works as expected. I assume setting usrloc's db_mode to 3 is recommended in this kind of setup?
For now I'm using: modparam("db_cluster", "cluster","data2=>voip1_data2=9s9p;voip2_data2=8s9p") on my voip1 machine, and the line below on the voip2 machine: modparam("db_cluster", "cluster","data2=>voip2_data2=9s9p;voip1_data2=8s9p")
The same configuration created coredumps on both machines previously.
Have played with usrloc and db_cluster a bit in the lab and think I found two bugs. I have not inspected the actual sql-commands, but this is based in my observations. Both sql-servers are running postgresql 9.1.4.
1) If the second server lacks an entry in the location table it will never be populated, while the primary is updated. This is a major flaw if the second server has been unavailable and then is back again it will never contain the same information as the primary.
I think this is because usrloc issues an UPDATE for the row it read, but the second server can not UPDATE an non existent row.
Deleting the entry from the primary server will issue an INSERT to both databases and then they are identical again, for that row at least.
2) If the primary lacks an entry and the second already has it, it will get an extra entry for that user. After a while though the stale entry will be pruned.
Probably similar reason as above. usrloc finds no entries in the table when reading, thus issuing INSERT.
Tried setting
modparam("usrloc", "db_check_update", 1)
but to no avail.
Even enabling
modparam("usrloc", "db_update_as_insert", 1)
will not fix issue #1.
Hello,
On 8/28/12 6:34 PM, Øyvind Kolbu wrote:
On 2012-08-24 at 10:48, Øyvind Kolbu wrote:
First impression is that everything is working now, thanks! At least registrations are getting populated in both databases from both servers. As I'm out traveling I havn't yet tested calling and whether or not the failover works as expected. I assume setting usrloc's db_mode to 3 is recommended in this kind of setup?
For now I'm using: modparam("db_cluster", "cluster","data2=>voip1_data2=9s9p;voip2_data2=8s9p") on my voip1 machine, and the line below on the voip2 machine: modparam("db_cluster", "cluster","data2=>voip2_data2=9s9p;voip1_data2=8s9p")
The same configuration created coredumps on both machines previously.
Have played with usrloc and db_cluster a bit in the lab and think I found two bugs. I have not inspected the actual sql-commands, but this is based in my observations. Both sql-servers are running postgresql 9.1.4.
If the second server lacks an entry in the location table it will never be populated, while the primary is updated. This is a major flaw if the second server has been unavailable and then is back again it will never contain the same information as the primary.
I think this is because usrloc issues an UPDATE for the row it read, but the second server can not UPDATE an non existent row.
Deleting the entry from the primary server will issue an INSERT to both databases and then they are identical again, for that row at least.
If the primary lacks an entry and the second already has it, it will get an extra entry for that user. After a while though the stale entry will be pruned.
Probably similar reason as above. usrloc finds no entries in the table when reading, thus issuing INSERT.
Tried setting
modparam("usrloc", "db_check_update", 1)
but to no avail.
what do you mean by the last line? This should be the solution to for the issue.
Even enabling
modparam("usrloc", "db_update_as_insert", 1)
will not fix issue #1.
This parameter is for some special backends, like cassadra, that don't take commands similar to sql update.
Cheers, Daniel
On 2012-08-28 at 21:56, Daniel-Constantin Mierla wrote:
On 8/28/12 6:34 PM, Øyvind Kolbu wrote:
Tried setting
modparam("usrloc", "db_check_update", 1)
but to no avail.
what do you mean by the last line? This should be the solution to for the issue.
That I tried that option, but without success. Any other suggestions? I can probably grab the sql statements received by the sql server.
Even enabling
modparam("usrloc", "db_update_as_insert", 1)
will not fix issue #1.
This parameter is for some special backends, like cassadra, that don't take commands similar to sql update.
OK.
On 8/28/12 10:23 PM, Øyvind Kolbu wrote:
On 2012-08-28 at 21:56, Daniel-Constantin Mierla wrote:
On 8/28/12 6:34 PM, Øyvind Kolbu wrote:
Tried setting
modparam("usrloc", "db_check_update", 1)
but to no avail.
what do you mean by the last line? This should be the solution to for the issue.
That I tried that option, but without success. Any other suggestions? I can probably grab the sql statements received by the sql server.
seeing the sql commands would help, also the log messages with debug=3 for that particular case.
Cheers, Daniel
Even enabling
modparam("usrloc", "db_update_as_insert", 1)
will not fix issue #1.
This parameter is for some special backends, like cassadra, that don't take commands similar to sql update.
OK.
On 2012-08-29 at 07:38, Daniel-Constantin Mierla wrote:
seeing the sql commands would help, also the log messages with debug=3
Now with "db_check_update" enabled. I've deleted the row for username 2549619 in the voip_location table from the secondary server between then re-registration.
I think the problem is that the check is done using only one of the "read table" connections, and not done for each of the "write table" connections.
Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:299]: executing db cluster query command Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:300]: serial operation - cluster [data2] (8/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7c9dfd0 (7) - [select contact,expires,q,callid,cseq,flags,cflags,user_agent,received,path,socket,methods,last_modified,ruid,instance,reg_id from voip_location where username='2549619' AND domain='hometest.voip.uio.no' or der by q] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:494]: 0xb7c9dfd0 PQresultStatus(PGRES_TUPLES_OK) PQgetResult(0x9058e78) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:108]: 16 columns returned from the query Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:155]: allocate 64 bytes for result names at 0xb7cd2db8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:165]: allocate 64 bytes for result types at 0xb7cd2e00 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[0] at 0xb7ca14d0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14d0)[0]=[contact] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[1] at 0xb7ca16e8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca16e8)[1]=[expires] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:158]: use DB1_DATETIME result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[2] at 0xb7ca15d0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca15d0)[2]=[q] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:151]: use DB1_DOUBLE result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[3] at 0xb7ca1530 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca1530)[3]=[callid] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[4] at 0xb7ca14a0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14a0)[4]=[cseq] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[5] at 0xb7ca14e0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14e0)[5]=[flags] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[6] at 0xb7ca16a8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca16a8)[6]=[cflags] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[7] at 0xb7ca14b0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14b0)[7]=[user_agent] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[8] at 0xb7ca14c0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14c0)[8]=[received] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[9] at 0xb7ca14f0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7ca14f0)[9]=[path] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[10] at 0xb7cd3098 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd3098)[10]=[socket] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[11] at 0xb7cd30a8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd30a8)[11]=[methods] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[12] at 0xb7cd30b8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd30b8)[12]=[last_modified] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:158]: use DB1_DATETIME result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[13] at 0xb7cd30c8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd30c8)[13]=[ruid] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[14] at 0xb7cd30d8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd30d8)[14]=[instance] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:166]: use DB1_STRING result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:126]: allocate 8 bytes for RES_NAMES[15] at 0xb7cd30e8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:133]: RES_NAMES(0xb7cd30e8)[15]=[reg_id] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:140]: use DB1_INT result type Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:222]: allocate for 16 columns 64 bytes in row buffer at 0xb7cd30f8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:184]: allocate 8 bytes for rows at 0xb7cd3140 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,0)=[sip:2549619@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][0] Column[contact]=[sip:2549619@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,1)=[2012-08-29 13:20:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][1] Column[expires]=[2012-08-29 13:20:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,2)=[-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][2] Column[q]=[-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,3)=[94f2f534-e3cc629f-5bd8343e@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][3] Column[callid]=[94f2f534-e3cc629f-5bd8343e@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,4)=[14] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][4] Column[cseq]=[14] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,5)=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][5] Column[flags]=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,6)=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][6] Column[cflags]=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,7)=[PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][7] Column[user_agent]=[PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,8)=[] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,9)=[] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,10)=[udp:129.240.253.197:5060] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][10] Column[socket]=[udp:129.240.253.197:5060] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,11)=[8159] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][11] Column[methods]=[8159] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,12)=[2012-08-29 13:18:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][12] Column[last_modified]=[2012-08-29 13:18:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,13)=[uloc-503dfa6f-7959-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][13] Column[ruid]=[uloc-503dfa6f-7959-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,14)=[] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:243]: PQgetvalue(0xb7c9dfd0,0,15)=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:252]: [0][15] Column[reg_id]=[0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:119]: allocate 320 bytes for row values at 0xb7cd3150 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:117]: converting STRING [sip:2549619@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:127]: allocate 27 bytes memory for STRING at 0xb7cd32b0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:157]: converting DATETIME [2012-08-29 13:20:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:106]: converting DOUBLE [-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:117]: converting STRING [94f2f534-e3cc629f-5bd8343e@193.157.149.56] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:127]: allocate 42 bytes memory for STRING at 0xb7cd32d8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:73]: converting INT [14] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:73]: converting INT [0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:73]: converting INT [0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:117]: converting STRING [PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:127]: allocate 43 bytes memory for STRING at 0xb7cd3310 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:56]: converting NULL value Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:56]: converting NULL value Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:117]: converting STRING [udp:129.240.253.197:5060] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:127]: allocate 25 bytes memory for STRING at 0xb7cd3348 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:73]: converting INT [8159] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:157]: converting DATETIME [2012-08-29 13:18:11] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:117]: converting STRING [uloc-503dfa6f-7959-1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:127]: allocate 21 bytes memory for STRING at 0xb7cd3370 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:56]: converting NULL value Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_val.c:73]: converting INT [0] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_res.c:267]: freeing row buffer at 0xb7cd30f8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x9058e78) result set Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [socket_info.c:583]: grep_sock_info - checking if host==us: 15==9 && [129.240.253.197] == [127.0.0.1] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [socket_info.c:587]: grep_sock_info - checking if port 5060 (advertise 0) matches port 5060 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [socket_info.c:583]: grep_sock_info - checking if host==us: 15==15 && [129.240.253.197] == [129.240.253.197] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [socket_info.c:587]: grep_sock_info - checking if port 5060 (advertise 0) matches port 5060 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:284]: executing db cluster free-result command Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:81]: freeing 16 columns Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[0] at 0xb7ca14d0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[1] at 0xb7ca16e8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[2] at 0xb7ca15d0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[3] at 0xb7ca1530 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[4] at 0xb7ca14a0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[5] at 0xb7ca14e0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[6] at 0xb7ca16a8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[7] at 0xb7ca14b0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[8] at 0xb7ca14c0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[9] at 0xb7ca14f0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[10] at 0xb7cd3098 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[11] at 0xb7cd30a8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[12] at 0xb7cd30b8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[13] at 0xb7cd30c8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[14] at 0xb7cd30d8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:85]: freeing RES_NAMES[15] at 0xb7cd30e8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:94]: freeing result names at 0xb7cd2db8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:99]: freeing result types at 0xb7cd2e00 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:54]: freeing 1 rows Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:68]: free VAL_STRING[0] 'sip:2549619@193.157.149.56' at 0xb7cd32b0 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:68]: free VAL_STRING[3] '94f2f534-e3cc629f-5bd8343e@193.157.149.56' at 0xb7cd32d8 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:68]: free VAL_STRING[7] 'PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054' at 0xb7cd3310 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:68]: free VAL_STRING[10] 'udp:129.240.253.197:5060' at 0xb7cd3348 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:68]: free VAL_STRING[13] 'uloc-503dfa6f-7959-1' at 0xb7cd3370 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_row.c:97]: freeing row values at 0xb7cd3150 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:62]: freeing rows at 0xb7cd3140 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: registrar [save.c:564]: 1 valid contacts Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: registrar [save.c:586]: 1 contacts after commit Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [sruid.c:176]: new sruid is [uloc-503dfa6f-795c-1] (1 / 20) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:356]: executing db cluster update command Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:357]: parallel operation - cluster [data2] (9/0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7c9df08 (7) - [update voip_location set expires='2012-08-29 13:21:11',q=-1.00 ,cseq=15,flags=0,cflags=0,user_agent='PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054',received=NULL,path=NULL,socket='udp:129.240.253.197:5060',methods=8159,last_modified='2012-08-29 13:19:11',ruid='uloc-503dfa6f-7959-1',instance=NULL,reg_id=0 where username='2549619' AND contact='sip:2549619@193.157.149.56' AND callid='94f2f534-e3cc629f-5bd8343e@193.157.149.56' AND domain='hometest.voip.uio.no'] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:494]: 0xb7c9df08 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x9058e78) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x9058e78) result set Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:81]: freeing 0 columns Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:357]: parallel operation - cluster [data2] (9/1) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7c9dfd0 (7) - [update voip_location set expires='2012-08-29 13:21:11',q=-1.00 ,cseq=15,flags=0,cflags=0,user_agent='PolycomSoundPointIP-SPIP_331-UA/3.2.1.0054',received=NULL,path=NULL,socket='udp:129.240.253.197:5060',methods=8159,last_modified='2012-08-29 13:19:11',ruid='uloc-503dfa6f-7959-1',instance=NULL,reg_id=0 where username='2549619' AND contact='sip:2549619@193.157.149.56' AND callid='94f2f534-e3cc629f-5bd8343e@193.157.149.56' AND domain='hometest.voip.uio.no'] Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:494]: 0xb7c9dfd0 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x9058e78) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x9058e78) result set Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:81]: freeing 0 columns Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7cd2d90 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: db_cluster [dbcl_api.c:391]: executing db cluster affected-rows command Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: registrar [reply.c:368]: created Contact HF: Contact: sip:2549619@193.157.149.56;expires=120
Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: sl [sl.c:278]: reply in stateless mode (sl) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [msg_translator.c:206]: check_via_address(193.157.149.56, 193.157.149.56, 0) Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list 0xb5d23220 Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) Aug 29 13:19:11 voipt1-edge1 last message repeated 4 times Aug 29 13:19:11 voipt1-edge1 /nett/kamailio/current/sbin/kamailio[31068]: DEBUG: <core> [xavp.c:365]: destroying xavp list (nil)
Hello,
On 8/29/12 1:23 PM, Øyvind Kolbu wrote:
On 2012-08-29 at 07:38, Daniel-Constantin Mierla wrote:
seeing the sql commands would help, also the log messages with debug=3
Now with "db_check_update" enabled. I've deleted the row for username 2549619 in the voip_location table from the secondary server between then re-registration.
I think the problem is that the check is done using only one of the "read table" connections, and not done for each of the "write table" connections.
is usrloc module configured in db only mode?
Read operation cannot be done in 'parallel' fashion of the cluster, it is only serial or round robin, stopping at first successful query (even when there is no data records in the result of the query).
If usrloc keeps also the records in memory, there is no select done at runtime, only updates, which are write operations.
db_check_update is only for SQL UPDATE command, in MySQL you can see the number of affected rows and if it is 0, then the module does an insert (another write operation).
So, the question is why do you think the check is done on one 'read table', or you don't refer to the check of affected rows for UPDATE?
Cheers, Daniel
On 2012-08-29 at 20:16, Daniel-Constantin Mierla wrote:
is usrloc module configured in db only mode?
Yes, db_mode is 3.
Read operation cannot be done in 'parallel' fashion of the cluster, it is only serial or round robin, stopping at first successful query (even when there is no data records in the result of the query).
Not related to this thread, but would it be possible to force it to try until data is found?
If usrloc keeps also the records in memory, there is no select done at runtime, only updates, which are write operations.
db_check_update is only for SQL UPDATE command, in MySQL you can see the number of affected rows and if it is 0, then the module does an insert (another write operation).
I use Postgres, which as also returns the number of affected rows. Though perhaps Kamailio doesn't support it for Postgres.
From my previous post:
DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7c9df08 (7) - [update [...]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7cd2d90 DEBUG: db_postgres [km_dbase.c:494]: 0xb7c9df08 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x9058e78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x9058e78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7cd2d90
but it did succed and updated one row, though not reflected in the logs.
So, the question is why do you think the check is done on one 'read table', or you don't refer to the check of affected rows for UPDATE?
Hm, perhaps I was a bit confused on how the affected rows works. Anyhow if a row is missing on a secondary server the UPDATE will fail and it will never be fixed with an INSERT.
Similar problem if the inital SELECT from the read-only sql-server returns noting, it will perform an INSERT on each of the write-servers, without first attempting to UPDATE. This will create duplicate contacts if the contact already exists on the write-servers. The stale entry will of course be pruned after a while..
Below is from another experiment where I deleted the row in the location-table on the primary server, but left it on the secondary server:
DEBUG: auth [api.c:218]: check_response: Authorization is OK [...] DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) DEBUG: db_cluster [dbcl_api.c:299]: executing db cluster query command DEBUG: db_cluster [dbcl_api.c:300]: serial operation - cluster [data2] (8/0) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03fd0 (7) - [select [... long statement ...]] [...] DEBUG: db_postgres [km_res.c:211]: no rows returned from the query DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: usrloc [udomain.c:599]: aor 2549619@hometest.voip.uio.no not found in table voip_location DEBUG: db_cluster [dbcl_api.c:284]: executing db cluster free-result command [...] DEBUG: <core> [sruid.c:176]: new sruid is [uloc-503e5fe0-26a8-4] (4 / 20) DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) DEBUG: db_cluster [dbcl_api.c:333]: executing db cluster insert command DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (9/0) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03f08 (7) - [insert into voip_location [... long statment ..]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7d076b8 DEBUG: db_postgres [km_dbase.c:494]: 0xb7d03f08 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x933fe78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7d076b8 DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (9/1) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03fd0 (7) - [insert into voip_location [ ... another blind insert ]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7d076b8 DEBUG: db_postgres [km_dbase.c:494]: 0xb7d03fd0 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x933fe78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7d076b8
Hello,
On 8/29/12 9:15 PM, Øyvind Kolbu wrote:
On 2012-08-29 at 20:16, Daniel-Constantin Mierla wrote:
is usrloc module configured in db only mode?
Yes, db_mode is 3.
this might not be very suitable for db_cluster usage if one db server is done, because right now the reading is done to the first available server.
Read operation cannot be done in 'parallel' fashion of the cluster, it is only serial or round robin, stopping at first successful query (even when there is no data records in the result of the query).
Not related to this thread, but would it be possible to force it to try until data is found?
No, you have to do some C coding. The target was to offer high availability to access a database server, when one is down, try next.
Perhaps you can add some cross replication at database server layer.
If usrloc keeps also the records in memory, there is no select done at runtime, only updates, which are write operations.
db_check_update is only for SQL UPDATE command, in MySQL you can see the number of affected rows and if it is 0, then the module does an insert (another write operation).
I use Postgres, which as also returns the number of affected rows. Though perhaps Kamailio doesn't support it for Postgres.
I am not a postgres user, but if it exports it, then it is used automatically by usrloc module.
From my previous post:
DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7c9df08 (7) - [update [...]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7cd2d90 DEBUG: db_postgres [km_dbase.c:494]: 0xb7c9df08 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x9058e78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x9058e78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7cd2d90
but it did succed and updated one row, though not reflected in the logs.
So, the question is why do you think the check is done on one 'read table', or you don't refer to the check of affected rows for UPDATE?
Hm, perhaps I was a bit confused on how the affected rows works. Anyhow if a row is missing on a secondary server the UPDATE will fail and it will never be fixed with an INSERT.
IIRC, if the operation was successful, affected rows checks the last used connection. In a cluster, the operation is considered to be successful when int succeeded on a db server node.
I think you are looking more for replication, rather that high availability of the db layer. This is not done by db_cluster, if the nodes are up, then all should be fine, but if one goes down and then back up, its content is not synchronized, should be done by the db server itself.
Cheers, Daniel
Similar problem if the inital SELECT from the read-only sql-server returns noting, it will perform an INSERT on each of the write-servers, without first attempting to UPDATE. This will create duplicate contacts if the contact already exists on the write-servers. The stale entry will of course be pruned after a while..
Below is from another experiment where I deleted the row in the location-table on the primary server, but left it on the secondary server:
DEBUG: auth [api.c:218]: check_response: Authorization is OK [...] DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) DEBUG: db_cluster [dbcl_api.c:299]: executing db cluster query command DEBUG: db_cluster [dbcl_api.c:300]: serial operation - cluster [data2] (8/0) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03fd0 (7) - [select [... long statement ...]] [...] DEBUG: db_postgres [km_res.c:211]: no rows returned from the query DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: usrloc [udomain.c:599]: aor 2549619@hometest.voip.uio.no not found in table voip_location DEBUG: db_cluster [dbcl_api.c:284]: executing db cluster free-result command [...] DEBUG: <core> [sruid.c:176]: new sruid is [uloc-503e5fe0-26a8-4] (4 / 20) DEBUG: db_cluster [dbcl_api.c:436]: use table (voip_location) - cluster [data2] DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/0) DEBUG: db_cluster [dbcl_api.c:455]: set write table (voip_location) - cluster [data2] (9/1) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (8/0) DEBUG: db_cluster [dbcl_api.c:445]: set read table (voip_location) - cluster [data2] (7/0) DEBUG: db_cluster [dbcl_api.c:333]: executing db cluster insert command DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (9/0) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03f08 (7) - [insert into voip_location [... long statment ..]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7d076b8 DEBUG: db_postgres [km_dbase.c:494]: 0xb7d03f08 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x933fe78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7d076b8 DEBUG: db_cluster [dbcl_api.c:334]: parallel operation - cluster [data2] (9/1) DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 26 chars, out: 26 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 41 chars, out: 41 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 42 chars, out: 42 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 24 chars, out: 24 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_val.c:163]: PQescapeStringConn: in: 20 chars, out: 20 chars DEBUG: db_postgres [km_dbase.c:224]: sending query ok: 0xb7d03fd0 (7) - [insert into voip_location [ ... another blind insert ]] DEBUG: <core> [db_res.c:118]: allocate 28 bytes for result set at 0xb7d076b8 DEBUG: db_postgres [km_dbase.c:494]: 0xb7d03fd0 PQresultStatus(PGRES_COMMAND_OK) PQgetResult(0x933fe78) DEBUG: db_postgres [km_dbase.c:393]: PQclear(0x933fe78) result set DEBUG: <core> [db_res.c:81]: freeing 0 columns DEBUG: <core> [db_res.c:136]: freeing result set at 0xb7d076b8
On 2012-08-30 at 10:09, Daniel-Constantin Mierla wrote:
On 8/29/12 9:15 PM, Øyvind Kolbu wrote:
On 2012-08-29 at 20:16, Daniel-Constantin Mierla wrote:
is usrloc module configured in db only mode?
Yes, db_mode is 3.
this might not be very suitable for db_cluster usage if one db server is done, because right now the reading is done to the first available server.
I choose 3 because of the usrloc documentation: «The mode is useful if you configure more servers sharing the same DB without any replication at SIP level.» As I want multiple servers to write to the same database it seemed as the best option.
No, you have to do some C coding. The target was to offer high availability to access a database server, when one is down, try next.
OK, will see if I get the time to do that.
Perhaps you can add some cross replication at database server layer.
Yes, I've asked our DBAs for that, but they are not ready yet.
Hm, perhaps I was a bit confused on how the affected rows works. Anyhow if a row is missing on a secondary server the UPDATE will fail and it will never be fixed with an INSERT.
IIRC, if the operation was successful, affected rows checks the last used connection. In a cluster, the operation is considered to be successful when int succeeded on a db server node.
I think you are looking more for replication, rather that high availability of the db layer. This is not done by db_cluster, if the nodes are up, then all should be fine, but if one goes down and then back up, its content is not synchronized, should be done by the db server itself.
Yes, I actually want both, HA + replication, by using db_cluster as the replicator. And as I've demonstrated the location-table on non-primary servers will lack entries after downtime, which is bad.
If this indeed is impossible I've have to continue our current scheme with SIP level replication.
On 8/30/12 10:29 AM, Øyvind Kolbu wrote:
On 2012-08-30 at 10:09, Daniel-Constantin Mierla wrote:
On 8/29/12 9:15 PM, Øyvind Kolbu wrote:
On 2012-08-29 at 20:16, Daniel-Constantin Mierla wrote:
is usrloc module configured in db only mode?
Yes, db_mode is 3.
this might not be very suitable for db_cluster usage if one db server is done, because right now the reading is done to the first available server.
I choose 3 because of the usrloc documentation: «The mode is useful if you configure more servers sharing the same DB without any replication at SIP level.» As I want multiple servers to write to the same database it seemed as the best option.
Yes, it is what it says, but you have two database servers. Your two kamailios don't connect to a single instance of DB server.
No, you have to do some C coding. The target was to offer high availability to access a database server, when one is down, try next.
OK, will see if I get the time to do that.
Perhaps you can add some cross replication at database server layer.
Yes, I've asked our DBAs for that, but they are not ready yet.
Hm, perhaps I was a bit confused on how the affected rows works. Anyhow if a row is missing on a secondary server the UPDATE will fail and it will never be fixed with an INSERT.
IIRC, if the operation was successful, affected rows checks the last used connection. In a cluster, the operation is considered to be successful when int succeeded on a db server node.
I think you are looking more for replication, rather that high availability of the db layer. This is not done by db_cluster, if the nodes are up, then all should be fine, but if one goes down and then back up, its content is not synchronized, should be done by the db server itself.
Yes, I actually want both, HA + replication, by using db_cluster as the replicator. And as I've demonstrated the location-table on non-primary servers will lack entries after downtime, which is bad.
Replication is done with parallel writing as long as all nodes are available, but, better said, you look for re-synchronization after downtime, which is another story, not easy to code, because it is db specific.
If this indeed is impossible I've have to continue our current scheme with SIP level replication.
If you use db mode 3, then you can do database level replication, is the same.
Daniel
On 2012-08-30 at 11:32, Daniel-Constantin Mierla wrote:
On 8/30/12 10:29 AM, Øyvind Kolbu wrote:
Yes, I actually want both, HA + replication, by using db_cluster as the replicator. And as I've demonstrated the location-table on non-primary servers will lack entries after downtime, which is bad.
Replication is done with parallel writing as long as all nodes are available, but, better said, you look for re-synchronization after downtime, which is another story, not easy to code, because it is db specific.
I don't want Kamailio to synchronise my data, but I think it is reasonable to expect it to treat the write targets individual and independent of the result from the initial reading.
Perhaps enabling db_update_as_insert is the only current option.
If this indeed is impossible I've have to continue our current scheme with SIP level replication.
If you use db mode 3, then you can do database level replication, is the same.
------- ------- | DB1 | | DB2 | ------- ------- | | | | | | ------- -------- | LOC1| | LOC2 | ------- -------- \ / ---------- | Phones | ----------
The above setup is my scenario. When everything is up LOC1 will use DB1 for reading and write to both DB1 and DB2. Similarly LOC2 will use DB2 for reading and write to both DB1 and DB2. Both uses the "other" DB as failover for reading. LOC1 and LOC2 are setup with even load in an SRV record.
- While DB2 is down, say reboot for a new kernel, a phone A boots and registers at LOC1 and is populated in the DB1 database. Reading works fine from LOC2 to DB1. - DB2 is back again. - Phone A re-registers at LOC1. The previous entry is found in the location table and an UPDATE is issued for both DB1 and DB2, but DB2 will still lack the entry.
DB2 will _never_ get an entry for until phone A boots and gets a new Call-ID or for some reason phone A chooses to register with LOC2 instead. Then a duplicate entry will end up in DB1, as LOC2 will blindly issue an INSERT to both DB1 and DB2.
As the location servers are evenly used, ~every second call to phone A will fail with 404.
On 8/30/12 12:50 PM, Øyvind Kolbu wrote:
On 2012-08-30 at 11:32, Daniel-Constantin Mierla wrote:
On 8/30/12 10:29 AM, Øyvind Kolbu wrote:
Yes, I actually want both, HA + replication, by using db_cluster as the replicator. And as I've demonstrated the location-table on non-primary servers will lack entries after downtime, which is bad.
Replication is done with parallel writing as long as all nodes are available, but, better said, you look for re-synchronization after downtime, which is another story, not easy to code, because it is db specific.
I don't want Kamailio to synchronise my data, but I think it is reasonable to expect it to treat the write targets individual and independent of the result from the initial reading.
The write is independent of the read operation. Read cannot be performed in parallel, that results in duplicated records back to application.
Then, have in mind that there are several operations, one after the other: - update - which do update to all write db servers - test affected rows (which is always working on last write (update) connection) - insert if affected rows is 0
So it is not an atomic operation, like updated_and_if_affected_rows_is_0_then_insert. All this layer is done in usrloc, in sequential steps, working fine for one server, but not for multiple nodes.
I am not sure what it will take to implement this kind of operation inside the database drivers, then it may work. TBased on quick thoughts, the code is there, just that has to be structured for each db connector and exported via db api and propagated to db_cluster.
Perhaps enabling db_update_as_insert is the only current option.
This can end up in lot of records, as there is no update - if you set constraints at database layer, then you have failures on unique keys.
If this indeed is impossible I've have to continue our current scheme with SIP level replication.
If you use db mode 3, then you can do database level replication, is the same.
| DB1 | | DB2 |
| | | | | |
| LOC1| | LOC2 |
\ / ---------- | Phones | ----------
The above setup is my scenario. When everything is up LOC1 will use DB1 for reading and write to both DB1 and DB2. Similarly LOC2 will use DB2 for reading and write to both DB1 and DB2. Both uses the "other" DB as failover for reading. LOC1 and LOC2 are setup with even load in an SRV record.
- While DB2 is down, say reboot for a new kernel, a phone A boots and registers at LOC1 and is populated in the DB1 database. Reading works fine from LOC2 to DB1.
- DB2 is back again.
- Phone A re-registers at LOC1. The previous entry is found in the location table and an UPDATE is issued for both DB1 and DB2, but DB2 will still lack the entry.
DB2 will _never_ get an entry for until phone A boots and gets a new Call-ID or for some reason phone A chooses to register with LOC2 instead. Then a duplicate entry will end up in DB1, as LOC2 will blindly issue an INSERT to both DB1 and DB2.
As the location servers are evenly used, ~every second call to phone A will fail with 404.
You have to do cross replication at database layer and use db_cluster as read/write for failover access (e.g., try read/write on db1 and if fails, try the other one).
Cheers, Daniel
On 2012-08-30 at 13:32, Daniel-Constantin Mierla wrote:
Then, have in mind that there are several operations, one after the other:
- update - which do update to all write db servers
- test affected rows (which is always working on last write (update)
connection)
- insert if affected rows is 0
So it is not an atomic operation, like updated_and_if_affected_rows_is_0_then_insert. All this layer is done in usrloc, in sequential steps, working fine for one server, but not for multiple nodes.
After reading this mail and usrloc/ucontact.c I have a much better idea of how this works, thanks!
I am not sure what it will take to implement this kind of operation inside the database drivers, then it may work. TBased on quick thoughts, the code is there, just that has to be structured for each db connector and exported via db api and propagated to db_cluster.
This would be great.
You have to do cross replication at database layer and use db_cluster as read/write for failover access (e.g., try read/write on db1 and if fails, try the other one).
Yes, this is what we'll probably end up with. Thanks for all your answers!
On 8/30/12 4:05 PM, Øyvind Kolbu wrote:
On 2012-08-30 at 13:32, Daniel-Constantin Mierla wrote:
Then, have in mind that there are several operations, one after the other:
- update - which do update to all write db servers
- test affected rows (which is always working on last write (update)
connection)
- insert if affected rows is 0
So it is not an atomic operation, like updated_and_if_affected_rows_is_0_then_insert. All this layer is done in usrloc, in sequential steps, working fine for one server, but not for multiple nodes.
After reading this mail and usrloc/ucontact.c I have a much better idea of how this works, thanks!
ok
I am not sure what it will take to implement this kind of operation inside the database drivers, then it may work. TBased on quick thoughts, the code is there, just that has to be structured for each db connector and exported via db api and propagated to db_cluster.
This would be great.
I agree, the good part is that all is open source, so anyone can jump in and contribute new features they need ;-)
Cheers, Daniel
Øyvind Kolbu writes:
Yes, I actually want both, HA + replication, by using db_cluster as the replicator. And as I've demonstrated the location-table on non-primary servers will lack entries after downtime, which is bad.
that should not be the case if you use master-master replication in your db servers.
-- juha