[Users] presence in openser 1.2 ... cannot insert row?

Cesc cesc.santa at gmail.com
Thu Apr 12 19:16:54 CEST 2007


Hi,

I am testing the presence in openser1.2 ... running a ser.0.9.6 as a
registrar/proxy which forwards all presence messages to openser.
As a client, I use xlite 3.0 ...

I had an old semi-functional openser working, pre-1.2 ... and now I
upgraded to 1.2 from svn and it ain't working :)   The config file I
modified, as well as creating the DBTEXT files (all) from scratch
using the textdb.sh script.

Now, you can see the attached config file ... and the whireshark trace
with the subscribe and publish messages received ...
What happens can be seen here, in the log I get ... most interesting
are the lines with ERROR  written on them ;)
They tell that a new row could not be inserted ... and that some
lookup failed on the database ... I guess a familiar eye can catch
that easy.


4(2517) parse_headers: flags=78
 4(2517) t_lookup_request: start searching: hash=50044, isACK=0
 4(2517) DEBUG: RFC3261 transaction matching failed
 4(2517) DEBUG: t_lookup_request: no transaction found
 4(2517) =============================================================================================
 4(2517) The request method used is to [SUBSCRIBE] information.
(handle subscribe)
 4(2517) =============================================================================================
 1(2513) SIP Request:
 1(2513)  method:  <SUBSCRIBE>
 1(2513)  uri:     <sip:Chelsea at cafes.org>
 1(2513)  version: <SIP/2.0>
 1(2513) parse_headers: flags=2
 1(2513) Found param type 232, <branch> = <z9hG4bKa4e7.bd4e2945.0>; state=16
 1(2513) end of header reached, state=5
 1(2513) parse_headers: Via found, flags=2
 1(2513) parse_headers: this is the first via
 1(2513) After parse_msg...
 1(2513) preparing to run routing scripts...
 1(2513) parse_headers: flags=100
 1(2513) Found param type 232, <branch> =
<z9hG4bK-d87543-2641a76387057623-1--d87543->; state=6
 1(2513) Found param type 235, <rport> = <4326>; state=16
 1(2513) end of header reached, state=5
 1(2513) parse_headers: Via found, flags=100
 1(2513) parse_headers: this is the second via
 1(2513) DEBUG:maxfwd:is_maxfwd_present: value = 16
 1(2513) ==============================================================================================
 1(2513) parse_headers: flags=10
 1(2513) DEBUG:parse_to:end of header reached, state=10
 1(2513) DBUG:parse_to: display={}, ruri={sip:Chelsea at cafes.org}
 1(2513) DEBUG: get_hdr_field: <To> [25]; uri=[sip:Chelsea at cafes.org]
 1(2513) DEBUG: to body [<sip:Chelsea at cafes.org>
]
 1(2513) DEBUG: add_param: tag=1753b200
 1(2513) DEBUG:parse_to:end of header reached, state=29
 1(2513) DBUG:parse_to: display={"X-lite user 1"}, ruri={sip:Klaas at cafes.org}
 1(2513) New Message received: [7] from [sip:Klaas at cafes.org]
 1(2513) Request method used:[SUBSCRIBE].
 1(2513) =============================================================================================
 1(2513) DEBUG: t_newtran:  T on entrance=0xffffffff
 1(2513) parse_headers: flags=ffffffffffffffff
 1(2513) get_hdr_field: cseq <CSeq>: <1> <SUBSCRIBE>
 1(2513) DEBUG: get_hdr_body : content_length=0
 1(2513) found end of header
 1(2513) parse_headers: flags=78
 1(2513) t_lookup_request: start searching: hash=32330, isACK=0
 1(2513) DEBUG: RFC3261 transaction matching failed
 1(2513) DEBUG: t_lookup_request: no transaction found
 1(2513) =============================================================================================
 1(2513) The request method used is to [SUBSCRIBE] information.
(handle subscribe)
 1(2513) =============================================================================================
 1(2513) parse_headers: flags=ffffffffffffffff
 1(2513) PRESENCE: handle_subscribe: 'expires' found
 1(2513) PRESENCE: handle_subscribe: lexpire= 3600
 1(2513) PRESENCE: handle_subscribe: 'To' header ALREADY PARSED:
<sip:Chelsea at cafes.org>
 1(2513) PRESENCE:handle_subscribe: generating to_tag
 1(2513) PRESENCE :proces_rr: out rr [<sip:192.168.1.150;ftag=1753b200;lr=on>]
 1(2513) DBT:dbt_query: new res with 2 cols
 1(2513) DBT:dbt_result_new: new res with 2 cols
 1(2513) PRESENCE:handle_subscribe:The query in table watches returned no result
 1(2513) DBT:dbt_table_check_row: NULL value not allowed - field 0
 1(2513) DBT:db_insert: cannot insert the new row!!
 1(2513) DBT:db_insert: make clean!
 1(2513) PRESENCE:handle_subscribe: ERROR while inserting into watchers table
 1(2513) PRESENCE:handle_subscribe: ERROR occured
 1(2513) DEBUG: cleanup_uac_timers: RETR/FR timers reset
 1(2513) DEBUG: add_to_tail_of_timer[2]: 0xb5d79c78 (45)
 1(2513) DEBUG:tm:UNREF_UNSAFE: after is 0
 1(2513) DEBUG:destroy_avp_list: destroying list (nil)
 1(2513) receive_msg: cleaning up
 2(2515) SIP Request:
 2(2515)  method:  <PUBLISH>
 2(2515)  uri:     <sip:Klaas at cafes.org>
 2(2515)  version: <SIP/2.0>
 2(2515) parse_headers: flags=2
 2(2515) Found param type 232, <branch> = <z9hG4bK5aa3.0e4b2fb7.0>; state=16
 2(2515) end of header reached, state=5
 2(2515) parse_headers: Via found, flags=2
 2(2515) parse_headers: this is the first via
 2(2515) After parse_msg...
 2(2515) preparing to run routing scripts...
 2(2515) parse_headers: flags=100
 2(2515) Found param type 232, <branch> =
<z9hG4bK-d87543-7441d6073759ed7a-1--d87543->; state=6
 2(2515) Found param type 235, <rport> = <4326>; state=16
 2(2515) end of header reached, state=5
 2(2515) parse_headers: Via found, flags=100
 2(2515) parse_headers: this is the second via
 2(2515) DEBUG:maxfwd:is_maxfwd_present: value = 16
 2(2515) ==============================================================================================
 2(2515) parse_headers: flags=10
 2(2515) DEBUG:parse_to:end of header reached, state=10
 2(2515) DBUG:parse_to: display={"X-lite user 1"}, ruri={sip:Klaas at cafes.org}
 2(2515) DEBUG: get_hdr_field: <To> [38]; uri=[sip:Klaas at cafes.org]
 2(2515) DEBUG: to body ["X-lite user 1"<sip:Klaas at cafes.org>
]
 2(2515) DEBUG: add_param: tag=eb194522
 2(2515) DEBUG:parse_to:end of header reached, state=29
 2(2515) DBUG:parse_to: display={"X-lite user 1"}, ruri={sip:Klaas at cafes.org}
 2(2515) New Message received: [5] from [sip:Klaas at cafes.org]
 2(2515) Request method used:[PUBLISH].
 2(2515) =============================================================================================
 2(2515) DEBUG: t_newtran:  T on entrance=0xffffffff
 2(2515) parse_headers: flags=ffffffffffffffff
 2(2515) get_hdr_field: cseq <CSeq>: <1> <PUBLISH>
 2(2515) DEBUG: get_hdr_body : content_length=439
 2(2515) found end of header
 2(2515) parse_headers: flags=78
 2(2515) t_lookup_request: start searching: hash=15013, isACK=0
 2(2515) DEBUG: RFC3261 transaction matching failed
 2(2515) DEBUG: t_lookup_request: no transaction found
 2(2515) =============================================================================================
 2(2515) The request method used is to [PUBLISH] information. (handle publish)
 2(2515) =============================================================================================
 2(2515) parse_headers: flags=ffffffffffffffff
 2(2515) PRESENCE:handle_publish: SIP-If-Match not found
 2(2515) PRESENCE: generate_ETag: etag= a.1175401932.2515.3 / 19
  2(2515) PRESENCE:handle_publish: new etag  = a.1175401932.2515.3
 2(2515) PRESENCE: handle_publish: 'expires' found
 2(2515) PRESENCE: handle_publish: lexpire= 3600
 2(2515) PRESENCE: handle_publish: 'To' header ALREADY PARSED:
<sip:Klaas at cafes.org>
 2(2515) parse_headers: flags=ffffffffffffffff
 2(2515) PRESENCE:update_presentity: inserting 7 cols intotable
 2(2515) DBT:dbt_table_check_row: NULL value not allowed - field 0
 2(2515) DBT:db_insert: cannot insert the new row!!
 2(2515) DBT:db_insert: make clean!
 2(2515) PRESENCE:update_presentity: Error while inserting new presentity
 2(2515) PRESENCE:update_presentity: ERROR occured
 2(2515) PRESENCE:handle_publish: ERROR occured while updating presentity
 2(2515) PRESENCE: handle_publish: ERROR occured
 2(2515) DEBUG: cleanup_uac_timers: RETR/FR timers reset
 2(2515) DEBUG: add_to_tail_of_timer[2]: 0xb5d77d08 (45)
 2(2515) DEBUG:tm:UNREF_UNSAFE: after is 0
 2(2515) DEBUG:destroy_avp_list: destroying list (nil)
 2(2515) receive_msg: cleaning up
 4(2517) parse_headers: flags=ffffffffffffffff
 4(2517) PRESENCE: handle_subscribe: 'expires' found
 4(2517) PRESENCE: handle_subscribe: lexpire= 3600
 4(2517) PRESENCE: handle_subscribe: 'To' header ALREADY PARSED:
<sip:Klaas at cafes.org>
 4(2517) PRESENCE:handle_subscribe: generating to_tag
 4(2517) PRESENCE :proces_rr: out rr [<sip:192.168.1.150;ftag=e7740874;lr=on>]
 4(2517)
        [p_user]= Klaas  [p_domain]= cafes.org
        [w_user]= Klaas [w_domain]= cafes.org
 4(2517) [event]= presence.winfo
        [staus]= active
        [expires]= 3600
 4(2517) [to_tag]= 10.2517.1175401973.2
        [from_tag]= e7740874
 4(2517) PRESENCE: update_subscription ...
 4(2517)
        [p_user]= Klaas  [p_domain]= cafes.org
        [w_user]= Klaas [w_domain]= cafes.org
 4(2517) [event]= presence.winfo
        [staus]= active
        [expires]= 3600
 4(2517) [to_tag]= 10.2517.1175401973.2
        [from_tag]= e7740874
 4(2517) expires: 3600
 4(2517) PRESENCE:update_subscription:Inserting into database:
n_query_cols:14
 4(2517) [0] = to_user Klaas
 4(2517) [1] = to_domain cafes.org
 4(2517) [2] = from_user Klaas
 4(2517) [3] = from_domain cafes.org
 4(2517) [4] = event presence.winfo
 4(2517) [5] = event_id
 4(2517) [6] = callid MGUwMzgyNGFiMWE5ZGIxZjg1NGQwNDI5N2JlOTFmYjA.
 4(2517) [7] = to_tag 10.2517.1175401973.2
 4(2517) [8] = from_tag e7740874
 4(2517) [9] = contact sip:Klaas at 192.168.3.172:4326
 4(2517) [10] = status active
 4(2517) [11] = cseq 1
 4(2517) DBT:dbt_table_check_row: NULL value not allowed - field 0
 4(2517) DBT:db_insert: cannot insert the new row!!
 4(2517) DBT:db_insert: make clean!
 4(2517) PRESENCE:update_subscription: ERROR while storing new subscription
 4(2517) PRESENCE:update_presentity: ERROR occured
 4(2517) PRESENCE:handle_subscribe: ERROR while updating database
 4(2517) PRESENCE:handle_subscribe: ERROR occured
 4(2517) DEBUG: cleanup_uac_timers: RETR/FR timers reset
 4(2517) DEBUG: add_to_tail_of_timer[2]: 0xb5d763b8 (45)
 4(2517) DEBUG:tm:UNREF_UNSAFE: after is 0
 4(2517) DEBUG:destroy_avp_list: destroying list (nil)
 4(2517) receive_msg: cleaning up
 3(2516)  1(2513) SIP Request:
 1(2513)  method:  <SUBSCRIBE>
 1(2513)  uri:     <sip:Chelsea at cafes.org>
 1(2513)  version: <SIP/2.0>
 1(2513) parse_headers: flags=2
 1(2513) Found param type 232, <branch> = <z9hG4bKa4e7.bd4e2945.0>; state=16
 1(2513) end of header reached, state=5
 1(2513) parse_headers: Via found, flags=2
 1(2513) parse_headers: this is the first via
 1(2513) After parse_msg...
 1(2513) preparing to run routing scripts...
 1(2513) parse_headers: flags=100
 1(2513) Found param type 232, <branch> =
<z9hG4bK-d87543-2641a76387057623-1--d87543->; state=6
 1(2513) Found param type 235, <rport> = <4326>; state=16
 1(2513) end of header reached, state=5
 1(2513) parse_headers: Via found, flags=100
 1(2513) parse_headers: this is the second via
 1(2513) DEBUG:maxfwd:is_maxfwd_present: value = 16
 1(2513) ==============================================================================================
-------------- next part --------------
A non-text attachment was scrubbed...
Name: openser_dbtext.cfg
Type: application/octet-stream
Size: 5317 bytes
Desc: not available
Url : http://lists.kamailio.org/pipermail/users/attachments/20070412/87edcd5f/attachment.obj 
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: pub-sub-msg.txt
Url: http://lists.kamailio.org/pipermail/users/attachments/20070412/87edcd5f/attachment.txt 


More information about the Users mailing list