search

OpenSIPS / opensips

OpenSIPS is a GPL implementation of a multi-functionality SIP Server that targets to deliver a high-level technical solution (performance, security and quality) to be used in professional SIP server platforms.
https://opensips.org
Other
1.23k stars 571 forks source link

[BUG] ACC mysql Column cannot be null #2163

Closed telematico closed 3 years ago

telematico commented 4 years ago

OpenSIPS version you are running

version: opensips 2.4.8 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 0e68df7b0
running on Debian 10 (buster)

Describe the bug

Trying to account using ACC to mysql with extra fields and Non-Standard table on last Opensips 2.4 branch I receive errors because some columns can not be NULL. A clear error is trying to account a simple REGISTER, I receive the error: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1048): Column 'to_tag' cannot be null (obviously there is no to_tag)

The MySQL table is the same used by my old machine:

version: opensips 2.4.6 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 25f9070ab
main.c compiled on  with gcc 6.3.0
Running on Debian 9.11 (stretch)

but in the old machine the empty values are inserted as empty strings, not as NULL values.

in DB Schema (https://opensips.org/html/docs/db/db-schema-devel.html#AEN21) I confirmed the table definition is according the SPECS. With NOT NULL and Default value='' but note I'm using my own table, with extra values.

To Reproduce

Start last OpenSips 2.4 (Debian10) with ACC Mysql logging and try to account a REGISTER with do_accounting("log|db","cdr|failed") to your own table. I'm not sure if it's happening if using standard ACC table.

Expected behavior

The empty ACC variables (ie to_tag in REGISTER message) should be inserted as empty strings, not NULL values, as happening in older OpenSips Versions

Relevant System Logs

Jul  5 17:41:11 px5 SIPproxy[10607]: DEBUG: [MIlp0QphgDtHwLSgNvHLYQ..] [Z 5.2.28 rv2.8.115] authenticated. 
Jul  5 17:41:11 px5 SIPproxy[10607]: ACC: transaction answered: timestamp=1593963671;method=REGISTER;from_tag=721ea338;to_tag=;call_id=MIlp0QphgDtHwLSgNvHLYQ..;code=200;reason=OK;accountcode=;authuser=XXXXXX;callee=XXXXXX;srcip=XXX.XXX.XXX.XXX;extension=XXXX;mytype=X;useragent=Z 5.2.28 rv2.8.115
Jul  5 17:41:11 px5 SIPproxy[10607]: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1048): Column 'to_tag' cannot be null
Jul  5 17:41:11 px5 SIPproxy[10607]: ERROR:acc:acc_db_request: failed to insert into cdr_opensips_v24 table

OS/environment information Working machine is running Debian 9.11 and OpenSips 2.4.6 git revision: 25f9070ab Failing machine is running Debian 10 and Opensips 2.4.8 git revision: 0e68df7b0

Additional context

rvlad-patrascu commented 4 years ago

Hi @telematico,

I can't seem to reproduce this myself. Can you run opensips with debug level logs and post a chunk of log lines following this one ACC: transaction answered: ? I'm particularly interested in the logs starting with DBG:db_mysql:db_mysql_val2bind:.

telematico commented 4 years ago

Here is the debug:

Jul 10 08:32:55 px5 SIPproxy[18710]: ACC: transaction answered: timestamp=1594362775;method=REGISTER;from_tag=917782971;to_tag=;call_id=675099772-5064-1@BJC.BGI.B.BAD;code=200;reason=OK;accountcode=;authuser=XXXXXXX;callee=XXXXXXX;srcip=XX.XXX.XX.XX;idtrunk=;id_cliente=XXXX;extension=XX;mytype=5;useragent=Grandstream GXP2140 1.0.11.3
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7ff03e754950 (tail=140669816752912) MC=0x7ff03e754b88
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into cdr_proxyv24 (method,from_tag,to_tag,callid,sip_code,sip_reason,time,accountcode,authuser,callee,srcip,idtrunk,id_cliente,extension,mytype,useragent,callid_asterisk,ci,service_data,queue,sbc ) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)|
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:re_init_statement:  query  is <insert into cdr_proxyv24 (method,from_tag,to_tag,callid,sip_code,sip_reason,time,accountcode,authuser,callee,srcip,idtrunk,id_cliente,extension,mytype,useragent,callid_asterisk,ci,service_data,queue,sbc ) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)>, ptr=(nil)
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0x7ff03e759850) on connection: (0x7ff03e754950) 0x7ff03e754b10
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=8; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=9; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=30; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=7; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=7; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=12; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=4; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (13): len=2; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (14): len=1; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (15): len=28; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (16): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (17): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (18): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (19): len=0; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_val2bind: added val (20): len=15; type=254; is_null=0
Jul 10 08:32:55 px5 SIPproxy[18710]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Jul 10 08:32:55 px5 SIPproxy[18710]: CRITICAL:db_mysql:wrapper_single_mysql_stmt_execute: driver error (1048): Column 'to_tag' cannot be null
Jul 10 08:32:55 px5 SIPproxy[18710]: ERROR:acc:acc_db_request: failed to insert into cdr_proxyv24 table
razvancrainea commented 4 years ago

Hi, @telematico ! From the logs you provided, and double checking the code, I can say 100% that opensips is not writing a NULL value, but an empty string. Are you using any mysql triggers or something that would additionally process the data? This is just an idea got from here, but that would explain the weird behavior. Best regards, Răzvan

telematico commented 4 years ago

Hi @razvancrainea

No, there are no triggers. I tried to create a completely new test table, but the issue still happens. and if I change the table definition to allow NULL values, a NULL is inserted, not an empty string. I tried with different databases (an ancient Mysql5.5 and MariaDB 10.1.26) and still the same behavior.

I'm still investigating, but I I have a suspicion that it may be due to mariadb Client library. I found a change that may be related since MariaDB 10.2.4: https://mariadb.com/kb/en/null-values/#inserting On debian 9 db_mysql.so is linked to 10.1 libraries ( libmariadbclient.so.18) but on Debian 10 is linked to 10.3 (libmariadb.so.3)

do you think may be related?

thanks and regards,

rvlad-patrascu commented 4 years ago

The MariaDB change you are pointing out here is affecting what would happen when NULL values are present in the query from opensips and I am fairly confident that this is not the case. On the other hand it also seems highly improbable that the client library is sending a NULL value when opensips actually writes an empty string. Maybe you can confirm that opensips is sending the right queries by investigating on the mysql server side.

stale[bot] commented 3 years ago

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

telematico commented 3 years ago

Sorry but I finally removed the NULL field constraints in DB and everything is working. When I have more time I will continue investigating and if necessary I will reopen the bug. sorry for the inconvenience

john08burke commented 3 years ago

Hey @razvancrainea and @rvlad-patrascu! I have run into this before as well... and I normally just work an UPDATE statement to remove NULL constraint at startup as mentioned.

Here is some debug info that includes the mysql network trace and full debugs: opensips_mysql_issue.zip

Looking at the network trace in wireshark there is a complaint about Malformed Packet. It seems as if opensips is not sending the proper amount of params in the exec statement (10 vs 11 in my case), missing the to_tag I'm assuming. I'm not familiar with the mysql client proto, so maybe this is just how NULL is presented? In either case, it doesn't look like empty string is being sent.

Looking in logs, opensips seems to skip this field:

Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (1): len=12; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (2): len=0; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (3): len=36; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (5): len=9; type=254; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (7): len=4; type=3; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (9): len=4; type=3; is_null=0
Apr  7 19:38:22 [60] DBG:db_mysql:db_mysql_val2bind: added val (10): len=4; type=3; is_null=0

OpenSIPS version: 3.1 nightly. MariaDB version: mariadb:10.1 docker image