[OpenSIPS-Users] Opensips 1.5.1 acc table corruption

[Ian Blenke]

My employer runs well over a dozen production opensips 1.5.1 servers
as a hub/spoke topology on Ubuntu Hardy based servers with mysql
5.0.51a as a backend.

On our busier (but not really high volume) hub servers, we are seeing
corrupted acc table rows. The dead giveaway of a corrupt acc table row
is a datestamp of '0000-00-00 00:00:00', though a query for "method !=
'INVITE' and method != 'BYE'" is just as effective.

The oddest part is that it "comes and goes". Meaning, we will see days
without problems, and then a rash of invalid rows out of the blue. The
latest outbreak was this morning.

There appear to be only a few variants of this problem:

1. When the method is the first 16 characters of the RURI, ie:
"sip:8669337321 at 1"
2. When the method is "2.0 200 OK", the tailing part of the RURI
3. When the method the trailing two characters of the method plus 13
characters of the RURI, ie: "TE sip:866933732"

Here is a sample row where the method looks to be part of the RURI:

> mysql> select * from acc where id = 873979 \G
> *************************** 1. row ***************************
>            id: 873979
>        method: sip:8669337321 at 1
>      from_tag: SIP/2.0
> Via: SIP/2.0/UDP 169.25
>        to_tag: 13.70;branch=z9hG4bKf913.fbf962a7.0
> Via: SIP/
>        callid: .0/UDP  169.254.13.16:5060;branch=z9hG4bK1D0268F4
>
>      sip_code: rom
>    sip_reason: 88 at reston.pstn.redacted.com>;tag
>          time: 0000-00-00 00:00:00
>        cdr_id: NULL
>     caller_id: 16
> User-Agent: Cisc
>     callee_id: Forwards: 69
> Timest
>          cseq: 0
>   contact_uri: NULL
>    user_agent: 911DE-8199A76F-59D0E87E at 169.254.12.16.16BYE
> caller_domain: 0DE10DD0D-
> callee_domain: 12599
> 1 row in set (0.01 sec)

And here is an example where the method looks as if it's the end of
the request line:

> mysql> select * from acc where id = 873976 \G
> *************************** 1. row ***************************
>            id: 873976
>        method: 2.0 200 OK
> From
>      from_tag: y.lmno.tv>;tag=c7fb590f3e79b243;epid=04CEE460
> Call-ID: 103102af
>        to_tag: E
> Via: SIP/2.0/TCP 169.254.13.100:5060;received=169.254.12.100;e
>        callid:
> pvrscom150;branch=z9hG4bKa64d965bd61826604ff352418c0432853138.95
>      sip_code: aac
>    sip_reason: IP/2.0/TCP 127.0.0.1;branch=z9hG
>          time: 0000-00-00 00:00:00
>        cdr_id: NULL
>     caller_id: llow: MESSAGE, INVIT
>     callee_id: FY, BYE
> Record-Rout
>          cseq: 9223372036854775807
>   contact_uri: NULL
>    user_agent: 69337231 at 169.254.13.20:5060
> User-Agent: DyLogic PSE.M
> caller_domain: 4.13.100:5060;transport=tcp;lr>
> Contact: "8669337321" <s
> callee_domain: 943353961
> 1 row in set (0.00 sec)

And finally, the last case:

> mysql> select * from acc where id = 873912 \G
> *************************** 1. row ***************************
>            id: 873912
>        method: TE sip:5507330670
>      from_tag:
> =on;ftag=DLb761cbe188;vsf=AAAAAGVkdB1ud3Z2AAB4HAkMAAgCAAMGLjIw;d
>        to_tag: 9.254.13.72>
> Call-ID: DL2bd3eab370 at DL-CZ-3598
> Fr
>        callid: m: "2654831750"
> <sip:2654831750 at 169.254.13.20>;tag=DLb761cbe188;
>      sip_code: Via
>    sip_reason: 0/UDP 169.254.13.70;branch=z9hG4
>          time: 0000-00-00 00:00:00
>        cdr_id: NULL
>     caller_id: hG4bK-13218ee492-DL
>     callee_id: @169.254.13.20:5060
>          cseq: 0
>   contact_uri: NULL
>    user_agent: p:reston.hub.sip.redacted.com;lr>
>
> v=0
> o=8669337321 206167750
> caller_domain: .MS 4.3.13
> Content-Type: application/sdp
> Content-Length: 248
>
> callee_domain: 1933320250
> 1 row in set (0.00 sec)

These were altered slightly to obscure the IP addresses, as well as
customer phone numbers, but are otherwise as they appear in that hub's
database.

The problem does appear to be load based in that the busier the
server, the more of these seem to appear.

We are getting a number of mysql errors in our logs that are also
unexplainable that roughly coincide with these events (repeated many
times):

> /usr/sbin/opensips[11190]: ERROR:db_mysql:db_mysql_do_prepared_query:
>  mysql_stmt_bind_param() failed: Using unsupported buffer type: 808333624
>  (parameter: 3)
> ...
> /usr/sbin/opensips[11188]: ERROR:db_mysql:db_mysql_do_prepared_query:
>  mysql_stmt_execute() failed(2): (1210) Incorrect arguments to
>  mysql_stmt_execute
> ...
> /usr/sbin/opensips[11190]:
>  ERROR:db_mysql:re_init_statement: failed while mysql_stmt_prepare: (1243)
>  Unknown prepared statement handler (1) given to mysql_stmt_close

A previous occurrence of this problem reported a different unsupported
buffer type:

> /usr/sbin/opensips[11209]: ERROR:db_mysql:db_mysql_do_prepared_query:
>  mysql_stmt_bind_param() failed: Using unsupported buffer type: 51
>  (parameter: 8)
> /usr/sbin/opensips[11209]: ERROR:dialog:update_dialog_dbinfo: could not update
>  database info

My employer does not bill off of these servers, so this isn't critical
to our business, but it is still something we want to address for
obvious reasons.

Thank you for your time,

-- 
- Ian Blenke <ian at blenke.com> http://ian.blenke.com