[Home]

Summary:ASTERISK-20538: inconsistent ast_verb numbering
Reporter:Walter Doekes (wdoekes)Labels:
Date Opened:2012-10-09 08:01:20Date Closed:2012-10-30 01:36:45
Priority:TrivialRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:1.8.18.0 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:{noformat}
asterisk-1.8.x$ find . -name '*.c' | xargs grep -h 'ast_verb([0-9]' | sed -e 's/.*ast_verb(//;s/,.*//' | sort | uniq -c
   128 0
   136 1
     3 10
     8 11
   131 2
   565 3
    85 4
    13 6
{noformat}

I.e. 3 uses of ast_verb(10) and 8 of ast_verb(11). Is there a good reason for this? Or could those calls be lowered to the 5-6 range?

{noformat}
asterisk-1.8.x$ find . -name '*.c' | xargs grep -l 'ast_verb(10,'
./cel/cel_odbc.c
./res/res_odbc.c
./cdr/cdr_adaptive_odbc.c
{noformat}
{noformat}
asterisk-1.8.x$ find . -name '*.c' | xargs grep -l 'ast_verb(11,'
./cel/cel_odbc.c
./cel/cel_pgsql.c
./cdr/cdr_odbc.c
./cdr/cdr_pgsql.c
./cdr/cdr_adaptive_odbc.c
{noformat}
Comments:By: Mark Michelson (mmichelson) 2012-10-10 16:49:13.325-0500

I believe the large numbers are used because those messages are overly verbose and would print way more often than what people would want to see. By choosing high numbers like 10 or 11, it means people have to specifically enable verbosity at that ridiculously high level in order to see those messages. Reducing their level would defeat the purpose.
By: Walter Doekes (wdoekes) 2012-10-11 02:54:42.671-0500

That would be a good explanation, if it weren't for the fact that some of these are not at all common.

I've ran verbose=20 since forever, so I did see them, but I do like to notice things like these:

{noformat}
VERBOSE[xxx] cdr_odbc.c:        > cdr_odbc: Error in ExecDirect: -1
WARNING[xxx] res_odbc.c: SQL Execute error! Verifying connection to my_database [my_database]...
WARNING[xxx] res_odbc.c: Connection is down attempting to reconnect...
NOTICE[xxx] res_odbc.c: Connecting my_database
NOTICE[xxx] res_odbc.c: res_odbc: Connected to my_database [my_database]
{noformat}

This is a CDR insertion that takes too long, after which my mysql-proxy switches over to a different database server.

This is not verbose spam, these are rare cases:

cdr/cdr_odbc.c: execute_cb(), called and retried once by ast_odbc_direct_execute.
{noformat}
       ODBC_res = SQLExecDirect(stmt, (unsigned char *)sqlcmd, SQL_NTS);

       if ((ODBC_res != SQL_SUCCESS) && (ODBC_res != SQL_SUCCESS_WITH_INFO)) {
               ast_verb(11, "cdr_odbc: Error in ExecDirect: %d\n", ODBC_res);
               SQLFreeHandle(SQL_HANDLE_STMT, stmt);
               return NULL;
       }
{noformat}

If it reconnects and succeeds, I have no way of knowing why it reconnected. If it fails after the reconnect, I only get this piece of info:
{noformat}
ast_log(LOG_ERROR, "CDR direct execute failed\n");
{noformat}

The other two instances of level 11 logging concern the module_unload. This is not something we do every couple of minutes either.

OTOH, if I look at the other modules, I do agree that those could become rather spammy.

.. I should probably change this ticket to "inconsistent ast_verb numbering in cdr_odbc" and upload a patch ;)
By: Rusty Newton (rnewton) 2012-10-15 09:23:45.507-0500

{quote}
I should probably change this ticket to "inconsistent ast_verb numbering in cdr_odbc" and upload a patch
{quote}

Feel free! Thanks Walter.
By: Matt Jordan (mjordan) 2012-10-29 20:49:50.973-0500

I can't remember, didn't you commit a patch to fix a lot of these recently?  If so, does this issue need to remain open?  (Erin is working on getting the subversion tab back... I'm practically blind without it sometimes)
By: Walter Doekes (wdoekes) 2012-10-30 01:34:01.215-0500

Indeed I did. Forgot to close this one.

http://lists.digium.com/pipermail/asterisk-commits/2012-October/057332.html
By: Walter Doekes (wdoekes) 2012-10-30 01:36:22.236-0500

Oh.. I didn't forget.

"(closes issue ASTERISK-20538)" is in the log.

What went wrong?