12 Apr
2007
12 Apr
'07
1:16 p.m.
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@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@cafes.org}
1(2513) DEBUG: get_hdr_field: <To> [25]; uri=[sip:Chelsea@cafes.org]
1(2513) DEBUG: to body [<sip:Chelsea@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@cafes.org}
1(2513) New Message received: [7] from [sip:Klaas@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@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@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@cafes.org}
2(2515) DEBUG: get_hdr_field: <To> [38]; uri=[sip:Klaas@cafes.org]
2(2515) DEBUG: to body ["X-lite user 1"<sip:Klaas@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@cafes.org}
2(2515) New Message received: [5] from [sip:Klaas@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@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@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@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@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)
==============================================================================================