[sr-dev] invalid type (3) or nul (0) version columns for trusted (kamailio 3.1 latest from git)

Tue Oct 19 12:00:30 CEST 2010

  I've got some more debug information,
but it almost looks like a race condition.

When I turn of all debugging the problem occurs more often.
When I turn on debugging (level 4 or 5) I almost never see the error.

But I finally have some debugging info:

Oct 18 19:40:53 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[sr_module.c:828]: DEBUG: init_mod_child (96): permissions
Oct 18 19:40:53 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db.c:294]: connection 0x958390 found in pool
Oct 18 19:40:53 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_val.c:163]: PQescapeStringConn: in: 7 chars, out: 7 chars
Oct 18 19:40:53 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_dbase.c:149]: 0x959aa0 PQsendQuery(select table_version from version 
where table_name='trusted')
Oct 18 19:40:53 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_res.c:118]: allocate 48 bytes for result set at 0x94d790

Then 47 seconds later (in the mean time, nothing is reported for pid 29227):

Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_dbase.c:403]: 0x959aa0 PQresultStatus(PGRES_TUPLES_OK) 
PQgetResult(0x139aca20)
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:108]: 1 columns returned from the query
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_res.c:155]: allocate 8 bytes for result names at 0x94b1f0
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_res.c:165]: allocate 4 bytes for result types at 0x942140
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:126]: allocate 16 bytes for RES_NAMES[0] at 0x9599b0
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:133]: RES_NAMES(0x9599b0)[0]=[password]
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:166]: use DB1_STRING result type
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:222]: allocate for 1 columns 8 bytes in row buffer at 0x959538
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_res.c:184]: allocate 16 bytes for rows at 0x9598d8
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:243]: PQgetvalue(0x959aa0,0,0)=[mAC4QMyW262E]
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:252]: [0][0] Column[password]=[mAC4QMyW262E]
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_row.c:119]: allocate 32 bytes for row values at 0x94d820
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_val.c:117]: converting STRING [mAC4QMyW262E]
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: <core> 
[db_val.c:127]: allocate 13 bytes memory for STRING at 0x9596d0
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_res.c:267]: freeing row buffer at 0x959538
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: DEBUG: db_postgres 
[km_dbase.c:302]: PQclear(0x139aca20) result set
Oct 18 19:41:40 localhost /sbin/kamailio[29227]: ERROR: <core> 
[db.c:387]: invalid type (3) or nul (0) version columns for trusted

I have more debugging lines if someone has an idea.

But it appears that pid 29227 is sending a query, and when it continues 
it's working with the results from a completely different query.

Regards,
Robert

On 10/12/2010 04:30 PM, Robert Verspuy wrote:
> I've got a strange issue with the latest kamailio. I also had this 
> problem with kamailio 3.0.3 downloaded from the webpage.
>
> I can start kamailio, but after a while (sometimes within one minuten, 
> sometimes after an hour),
> I get the following log errors:
>
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: <core> [db.c:387]: 
> invalid type (3) or nul (0) version columns for trusted
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: <core> [db.c:405]: 
> querying version for table trusted
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: permissions 
> [trusted.c:249]: error during table version check.
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: <core> 
> [sr_module.c:832]: init_mod_child(): Error while initializing module 
> permissions (//lib/kamailio/modules_k/permissions.so)
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: <core> [pt.c:481]: 
> ERROR: fork_tcp_process(): init_child failed for process 10, pid 
> 26621, "tcp receiver child=0"
> Oct 12 15:46:24 sp01 /sbin/kamailio[26621]: ERROR: <core> 
> [tcp_main.c:4811]: ERROR: tcp_main: fork failed: Success
> Oct 12 15:46:24 sp01 /sbin/kamailio[26625]: : <core> [pass_fd.c:103]: 
> ERROR: recv_all: 1st recv on 21 failed: Connection reset by peer
> Oct 12 15:46:24 sp01 /sbin/kamailio[26625]: : <core> 
> [tcp_main.c:3323]: ERROR: handle_tcp_child: read from tcp child 0  
> (pid 26621, no 10) Connection reset by peer [104]
> Oct 12 15:46:24 sp01 /sbin/kamailio[26625]: : <core> [pass_fd.c:293]: 
> ERROR: receive_fd: EOF on 19
> Oct 12 15:46:24 sp01 /sbin/kamailio[26611]: ALERT: <core> 
> [main.c:738]: child process 26621 exited normally, status=255
> Oct 12 15:46:24 sp01 /sbin/kamailio[26611]: INFO: <core> [main.c:756]: 
> INFO: terminating due to SIGCHLD
> Oct 12 15:46:24 sp01 /sbin/kamailio[26625]: INFO: <core> [main.c:807]: 
> INFO: signal 15 received
>
> Looking at the error message, it thinks that the column type of 
> table_version in the table version is a string (type 3), and it should 
> be an int (type 1).
> But in the database it really is an int.
>
> When I run kamailio with debugging on level 5, I see that it's trying 
> to run the "select table_version from version where 
> table_name='trusted'" several times when kamailio starts (for every 
> child thread).
> And then minutes, of even an hour later, it suddenly continues with 
> that check, but based on a database response from another query.
> This is the "select password from subscriber ....etc...".
> And that column is indeed an string.
>
> I'm using PostgreSQL 8.4 as server,
> but maybe someone has seen this before, or now where I have to start 
> looking?
> I first saw it yesterday when started to use the permissions module.
> I only see this with the trusted table,
> And always it uses the "select password from subscriber ... " response 
> when giving this error.
>
> So is this an error in the permissions module / trusted.c file?
> or something in auth_db that's not freeing the response correctly?
>
> Strange thing is, that is sometimes happens very quick, and sometimes 
> it can take an half hour or hour.
>
> I can mail the full log if anybody is interested and thinks he/she can 
> help me.
>
> With kind regards,
> Robert Verspuy
>
>
> -- 
> *Exa-Omicron*
> Patroonsweg 10
> 3892 DB Zeewolde
> Tel.: 088-OMICRON (66 427 66)
> http://www.exa-omicron.nl
>
>
> _______________________________________________
> sr-dev mailing list
> sr-dev at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev

-- 
*Exa-Omicron*
Patroonsweg 10
3892 DB Zeewolde
Tel.: 088-OMICRON (66 427 66)
http://www.exa-omicron.nl
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-dev/attachments/20101019/cef68260/attachment.htm>