[SR-Users] kamailio presence server using db_mongodb as database
José Seabra
joseseabra4 at gmail.com
Tue Aug 18 16:02:25 CEST 2015
Hello,
Now after kamailio startup seems that presence module is not working
correctly when receives a publish message, seems that is missing needed
fields for presence module
LOG debug=3
3(3749) DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request:
3(3749) DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method:
<PUBLISH>
3(3749) DEBUG: <core> [parser/msg_parser.c:610]: parse_msg(): uri: <
sip:301 at teste.teste.com.pt>
3(3749) DEBUG: <core> [parser/msg_parser.c:612]: parse_msg(): version:
<SIP/2.0>
3(3749) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK99ab.a0494a80806f1126d231ac6412d25d86.0>; state=16
3(3749) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
3(3749) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=2
3(3749) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers():
parse_headers: this is the first via
3(3749) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg...
3(3749) DEBUG: <core> [receive.c:177]: receive_msg(): preparing to run
routing scripts...
3(3749) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK99ab.dcb79f00000000000000000000000000.0>; state=16
3(3749) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
3(3749) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=100
3(3749) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers():
parse_headers: this is the second via
3(3749) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec():
end of header reached, state=10
3(3749) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [33]; uri=[sip:301 at teste.teste.com.pt]
3(3749) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG:
to body [<sip:301 at teste.teste.com.pt>
]
3(3749) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
3(3749) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=624
3(3749) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 69
3(3749) DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg
id=5 , global msg id=4 , T on entrance=0xffffffffffffffff
3(3749) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end
of header
3(3749) DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request:
start searching: hash=47769, isACK=0
3(3749) DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261
transaction matching failed
3(3749) DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
3(3749) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
6eb163b7ddd8b77ec80bdb2c6b73fe41
3(3749) INFO: <script>: Handling publish request - R=
sip:301 at teste.teste.com.pt ID=6869437916cdc134-3693 at 10.0.20.100
3(3749) DEBUG: presence [event_list.c:348]: search_event(): start event=
[dialog/5]
3(3749) DEBUG: presence [publish.c:316]: handle_publish(): SIP-If-Match
header not found
3(3749) DEBUG: presence [presentity.c:87]: generate_ETag(): etag=
a.1439906263.3749.5.0 / 21
3(3749) DEBUG: presence [publish.c:325]: handle_publish(): new etag =
a.1439906263.3749.5.0
3(3749) DEBUG: presence [publish.c:350]: handle_publish(): Expires header
found, value= 241
3(3749) DEBUG: presence [presentity.c:429]: update_presentity(): inserting
9 cols into table
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:1030]: db_mongodb_insert():
insert document: { "domain" : "teste.teste.com.pt", "username" : "301",
"event" : "dialog", "etag" : "a.1439906263.3749.5.0", "sender" : "", "body"
: { "$type" : "00", "$binary" :
"PD94bWwgdmVyc2lvbj0iMS4wIj8+CjxkaWFsb2ctaW5mbyB4bWxucz0idXJuOmlldGY6cGFyYW1zOnhtbDpuczpkaWFsb2ctaW5mbyIgdmVyc2lvbj0iMCIgc3RhdGU9ImZ1bGwiIGVudGl0eT0ic2lwOjMwMUB0ZXN0ZS5pdGNlbnRlci5jb20ucHQiPgogIDxkaWFsb2cgaWQ9IjMxMzQzMzM5MzkzMDM2MzIzNzM0MzQzMjMwMzkzMS02bnZ1eDRpYWZrenIiIGNhbGwtaWQ9IjMxMzQzMzM5MzkzMDM2MzIzNzM0MzQzMjMwMzkzMS02bnZ1eDRpYWZrenIiIGRpcmVjdGlvbj0iaW5pdGlhdG9yIj4KICAgIDxzdGF0ZT5Ucnlpbmc8L3N0YXRlPgogICAgPHJlbW90ZT4KICAgICAgPGlkZW50aXR5PnNpcDozMDJAdGVzdGUuaXRjZW50ZXIuY29tLnB0O3VzZXI9cGhvbmU8L2lkZW50aXR5PgogICAgICA8dGFyZ2V0IHVyaT0ic2lwOjMwMkB0ZXN0ZS5pdGNlbnRlci5jb20ucHQ7dXNlcj1waG9uZSIvPgogICAgPC9yZW1vdGU+CiAgICA8bG9jYWw+CiAgICAgIDxpZGVudGl0eT5zaXA6MzAxQHRlc3RlLml0Y2VudGVyLmNvbS5wdDwvaWRlbnRpdHk+CiAgICAgIDx0YXJnZXQgdXJpPSJzaXA6MzAxQHRlc3RlLml0Y2VudGVyLmNvbS5wdCIvPgogICAgPC9sb2NhbD4KICA8L2RpYWxvZz4KPC9kaWFsb2ctaW5mbz4K"
}, "received_time" : 1439906398, "priority" : 0, "expires" : 1439906639 }
3(3749) DEBUG: presence [presentity.c:104]: publ_send200ok(): send 200OK
reply
3(3749) DEBUG: presence [presentity.c:105]: publ_send200ok(): etag=
a.1439906263.3749.5.0 - len= 21
3(3749) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=5 global id=5 T start=0x7fee3ac83c58
3(3749) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
3(3749) DEBUG: <core> [msg_translator.c:158]: check_via_address():
(10.0.20.100, 10.0.20.100, 0)
3(3749) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize():
WARNING:vqm_resize: resize(0) called
3(3749) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
3(3749) DEBUG: tm [t_reply.c:647]: _reply_light(): DEBUG: reply sent out.
buf=0x7fee4d90d450: SIP/2.0 200 OK
Reco..., shmem=0x7fee3ac83920: SIP/2.0 200 OK
Reco
3(3749) DEBUG: tm [t_reply.c:657]: _reply_light(): DEBUG: _reply_light:
finished
3(3749) DEBUG: sl [sl.c:272]: send_reply(): reply in stateful mode (tm)
3(3749) DEBUG: presence [notify.c:1007]: get_subs_db(): querying database
table = active_watchers
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query(): query
to collection [active_watchers]
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query(): query
filter: { "presentity_uri" : "sip:301 at teste.teste.com.pt", "event" :
"dialog", "status" : 1, "contact" : { "$ne" : "" } }
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
columns filter: { "to_user" : 1, "to_domain" : 1, "from_user" : 1,
"from_domain" : 1, "watcher_username" : 1, "watcher_domain" : 1, "event_id"
: 1, "from_tag" : 1, "to_tag" : 1, "callid" : 1, "local_cseq" : 1,
"record_route" : 1, "contact" : 1, "expires" : 1, "reason" : 1,
"socket_info" : 1, "local_contact" : 1, "version" : 1 }
3(3749) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
for result set at 0x7fee4d90cda8
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:349]: db_mongodb_get_columns():
18 columns returned from the query
3(3749) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 144
bytes for result names at 0x7fee4d8fbe38
3(3749) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 72
bytes for result types at 0x7fee4d90d3c8
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[0] named: to_user
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[0] at 0x7fee4d90cfd0
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90cfd0)[0]=[to_user] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[1] named: to_domain
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[1] at 0x7fee4d90d018
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90d018)[1]=[to_domain] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[2] named: from_user
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[2] at 0x7fee4d90ccc0
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90ccc0)[2]=[from_user] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[3] named: from_domain
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[3] at 0x7fee4d8fba08
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d8fba08)[3]=[from_domain] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[4] named: watcher_username
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[4] at 0x7fee4d90c430
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90c430)[4]=[watcher_username] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[5] named: watcher_domain
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[5] at 0x7fee4d90c260
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90c260)[5]=[watcher_domain] (2)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[6] named: event_id
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[6] at 0x7fee4d90c340
3(3749) INFO: db_mongodb [mongodb_dbase.c:454]: db_mongodb_get_columns():
unhandled data type column (event_id) type id (10), use DB1_STRING as
default
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90c340)[6]=[event_id] (10)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[7] named: from_tag
3(3749) ERROR: db_mongodb [mongodb_dbase.c:381]: db_mongodb_get_columns():
field [from_tag] not found in result iterator
3(3749) ERROR: db_mongodb [mongodb_dbase.c:739]:
db_mongodb_store_result(): failed to set the columns
3(3749) ERROR: db_mongodb [mongodb_dbase.c:918]: db_mongodb_query():
failed to store result
3(3749) ERROR: db_mongodb [mongodb_dbase.c:927]: db_mongodb_query():
failed to do the query
3(3749) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 18 columns
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[0] at 0x7fee4d90cfd0
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[1] at 0x7fee4d90d018
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[2] at 0x7fee4d90ccc0
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[3] at 0x7fee4d8fba08
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[4] at 0x7fee4d90c430
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[5] at 0x7fee4d90c260
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[6] at 0x7fee4d90c340
3(3749) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
names at 0x7fee4d8fbe38
3(3749) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
types at 0x7fee4d90d3c8
3(3749) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result set
at 0x7fee4d90cda8
3(3749) ERROR: presence [notify.c:1065]: get_subs_db(): while querying
database
3(3749) ERROR: presence [notify.c:1191]: get_subs_dialog(): getting
dialogs from database
3(3749) DEBUG: presence [notify.c:1252]: publ_notify(): Could not find
subs_dialog
3(3749) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=5 global id=5 T start=0x7fee3ac83c58
3(3749) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
3(3749) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
3(3749) DEBUG: <core> [timer.c:574]: timer_add_safe(): timer_add called on
an active timer 0x7fee3ac83cd8 (0x7fee3aa24918, 0x7fee3aa24918), flags 201
3(3749) DEBUG: tm [t_funcs.c:148]: put_on_wait(): tm: put_on_wait:
transaction 0x7fee3ac83c58 already on wait
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
3(3749) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp
list (nil)
3(3749) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up
1(3747) DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request:
1(3747) DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method:
<PUBLISH>
1(3747) DEBUG: <core> [parser/msg_parser.c:610]: parse_msg(): uri: <
sip:301 at teste.teste.com.pt>
1(3747) DEBUG: <core> [parser/msg_parser.c:612]: parse_msg(): version:
<SIP/2.0>
1(3747) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK3a88.de19bf4f6bc602f9afbe64d352aaa48f.0>; state=16
1(3747) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
1(3747) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=2
1(3747) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers():
parse_headers: this is the first via
1(3747) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg...
1(3747) DEBUG: <core> [receive.c:177]: receive_msg(): preparing to run
routing scripts...
1(3747) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK3a88.b5fae090000000000000000000000000.0>; state=16
1(3747) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
1(3747) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=100
1(3747) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers():
parse_headers: this is the second via
1(3747) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec():
end of header reached, state=10
1(3747) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [33]; uri=[sip:301 at teste.teste.com.pt]
1(3747) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG:
to body [<sip:301 at teste.teste.com.pt>
]
1(3747) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
1(3747) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=741
1(3747) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 69
1(3747) DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg
id=5 , global msg id=4 , T on entrance=0xffffffffffffffff
1(3747) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2():
beginning of SIP-If-Match: yet=0x2d706973
1(3747) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2(): middle
of SIP-If-Match: yet=0x6d2d6669
1(3747) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2(): end of
SIP-If-Match
1(3747) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end
of header
1(3747) DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request:
start searching: hash=34979, isACK=0
1(3747) DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261
transaction matching failed
1(3747) DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
1(3747) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
9b1f4e306422fb9d9098596b86d0b3e0
1(3747) INFO: <script>: Handling publish request - R=
sip:301 at teste.teste.com.pt ID=6869437916cdc139-3695 at 10.0.20.100
1(3747) DEBUG: presence [event_list.c:348]: search_event(): start event=
[dialog/5]
1(3747) DEBUG: presence [publish.c:329]: handle_publish(): SIP-If-Match
header found
1(3747) DEBUG: presence [publish.c:338]: handle_publish(): existing etag
= a.1439906263.3749.5.0
1(3747) DEBUG: presence [publish.c:350]: handle_publish(): Expires header
found, value= 241
1(3747) DEBUG: presence [presentity.c:87]: generate_ETag(): etag=
a.1439906263.3747.5.1 / 21
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query():
query to collection [presentity]
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query(): query
filter: { "domain" : "teste.teste.com.pt", "username" : "301", "event" :
"dialog", "etag" : "a.1439906263.3749.5.0" }
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
columns filter: { "body" : 1, "sender" : 1 }
1(3747) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
for result set at 0x7fee4d90bd48
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:349]: db_mongodb_get_columns():
2 columns returned from the query
1(3747) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 16
bytes for result names at 0x7fee4d90cc88
1(3747) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 8
bytes for result types at 0x7fee4d8f4270
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[0] named: body
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[0] at 0x7fee4d8fbd80
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:426]: db_mongodb_get_columns():
use DB1_BLOB result type
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d8fbd80)[0]=[body] (5)
1(3747) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[1] named: sender
1(3747) ERROR: db_mongodb [mongodb_dbase.c:381]: db_mongodb_get_columns():
field [sender] not found in result iterator
1(3747) ERROR: db_mongodb [mongodb_dbase.c:739]:
db_mongodb_store_result(): failed to set the columns
1(3747) ERROR: db_mongodb [mongodb_dbase.c:918]: db_mongodb_query():
failed to store result
1(3747) ERROR: db_mongodb [mongodb_dbase.c:927]: db_mongodb_query():
failed to do the query
1(3747) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 2 columns
1(3747) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[0] at 0x7fee4d8fbd80
1(3747) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
names at 0x7fee4d90cc88
1(3747) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
types at 0x7fee4d8f4270
1(3747) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result set
at 0x7fee4d90bd48
1(3747) ERROR: presence [presentity.c:757]: update_presentity():
unsuccessful sql query
1(3747) ERROR: presence [publish.c:462]: handle_publish(): when updating
presentity
1(3747) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=5 global id=5 T start=0x7fee3ac80ed0
1(3747) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
1(3747) DEBUG: <core> [msg_translator.c:158]: check_via_address():
(10.0.20.100, 10.0.20.100, 0)
1(3747) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize():
WARNING:vqm_resize: resize(0) called
1(3747) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
1(3747) DEBUG: tm [t_reply.c:647]: _reply_light(): DEBUG: reply sent out.
buf=0x7fee4d90d2c0: SIP/2.0 500 Server I..., shmem=0x7fee3ac86738: SIP/2.0
500 Server I
1(3747) DEBUG: tm [t_reply.c:657]: _reply_light(): DEBUG: _reply_light:
finished
1(3747) DEBUG: sl [sl.c:272]: send_reply(): reply in stateful mode (tm)
1(3747) ERROR: <script>: Failed to handle publish request - R=
sip:301 at teste.teste.com.pt ID=6869437916cdc139-3695 at 10.0.20.100
1(3747) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=5 global id=5 T start=0x7fee3ac80ed0
1(3747) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
1(3747) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
1(3747) DEBUG: <core> [timer.c:574]: timer_add_safe(): timer_add called on
an active timer 0x7fee3ac80f50 (0x7fee3aa24948, 0x7fee3aa24948), flags 201
1(3747) DEBUG: tm [t_funcs.c:148]: put_on_wait(): tm: put_on_wait:
transaction 0x7fee3ac80ed0 already on wait
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
1(3747) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp
list (nil)
1(3747) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up
2(3748) DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request:
2(3748) DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method:
<PUBLISH>
2(3748) DEBUG: <core> [parser/msg_parser.c:610]: parse_msg(): uri: <
sip:302 at teste.teste.com.pt;user=phone>
2(3748) DEBUG: <core> [parser/msg_parser.c:612]: parse_msg(): version:
<SIP/2.0>
2(3748) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK2588.ae99aa97588f074549be2c16f8abf305.0>; state=16
2(3748) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
2(3748) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=2
2(3748) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers():
parse_headers: this is the first via
2(3748) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg...
2(3748) DEBUG: <core> [receive.c:177]: receive_msg(): preparing to run
routing scripts...
2(3748) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK2588.8dca50b0000000000000000000000000.0>; state=16
2(3748) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
2(3748) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=100
2(3748) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers():
parse_headers: this is the second via
2(3748) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec():
end of header reached, state=10
2(3748) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [44]; uri=[sip:302 at teste.teste.com.pt;user=phone]
2(3748) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG:
to body [<sip:302 at teste.teste.com.pt;user=phone>
]
2(3748) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
2(3748) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=752
2(3748) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 69
2(3748) DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg
id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
2(3748) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end
of header
2(3748) DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request:
start searching: hash=34898, isACK=0
2(3748) DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261
transaction matching failed
2(3748) DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
2(3748) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
6714bd30c1ad49bd6097d6f162964f6b
2(3748) INFO: <script>: Handling publish request - R=
sip:302 at teste.teste.com.pt;user=phone ID=6869437916cdc13a-3695 at 10.0.20.100
2(3748) DEBUG: presence [event_list.c:348]: search_event(): start event=
[dialog/5]
2(3748) DEBUG: presence [publish.c:316]: handle_publish(): SIP-If-Match
header not found
2(3748) DEBUG: presence [presentity.c:87]: generate_ETag(): etag=
a.1439906263.3748.6.0 / 21
2(3748) DEBUG: presence [publish.c:325]: handle_publish(): new etag =
a.1439906263.3748.6.0
2(3748) DEBUG: presence [publish.c:350]: handle_publish(): Expires header
found, value= 241
2(3748) DEBUG: presence [presentity.c:429]: update_presentity(): inserting
9 cols into table
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:1030]: db_mongodb_insert():
insert document: { "domain" : "teste.teste.com.pt", "username" : "302",
"event" : "dialog", "etag" : "a.1439906263.3748.6.0", "sender" : "", "body"
: { "$type" : "00", "$binary" :
"PD94bWwgdmVyc2lvbj0iMS4wIj8+CjxkaWFsb2ctaW5mbyB4bWxucz0idXJuOmlldGY6cGFyYW1zOnhtbDpuczpkaWFsb2ctaW5mbyIgdmVyc2lvbj0iMCIgc3RhdGU9ImZ1bGwiIGVudGl0eT0ic2lwOjMwMkB0ZXN0ZS5pdGNlbnRlci5jb20ucHQ7dXNlcj1waG9uZSI+CiAgPGRpYWxvZyBpZD0iMzEzNDMzMzkzOTMwMzYzMjM3MzQzNDMyMzAzOTMxLTZudnV4NGlhZmt6ciIgY2FsbC1pZD0iMzEzNDMzMzkzOTMwMzYzMjM3MzQzNDMyMzAzOTMxLTZudnV4NGlhZmt6ciIgbG9jYWwtdGFnPSJ4ZHc3ZjF2dmZ1IiByZW1vdGUtdGFnPSJxbHV6Njhvc2d0IiBkaXJlY3Rpb249InJlY2lwaWVudCI+CiAgICA8c3RhdGU+ZWFybHk8L3N0YXRlPgogICAgPHJlbW90ZT4KICAgICAgPGlkZW50aXR5PnNpcDozMDFAdGVzdGUuaXRjZW50ZXIuY29tLnB0PC9pZGVudGl0eT4KICAgICAgPHRhcmdldCB1cmk9InNpcDozMDFAMTkyLjE2OC4zMC4xMDc6NTA2MDthbGlhcz0xMDAuNjQuMjUwLjI1NH41NjcxMH4xO2xpbmU9OWFqdjU0MzkiLz4KICAgIDwvcmVtb3RlPgogICAgPGxvY2FsPgogICAgICA8aWRlbnRpdHk+c2lwOjMwMkB0ZXN0ZS5pdGNlbnRlci5jb20ucHQ7dXNlcj1waG9uZTwvaWRlbnRpdHk+CiAgICAgIDx0YXJnZXQgdXJpPSJzaXA6MzAyQDE5Mi4xNjguMzAuMTI1OjUwNjA7YWxpYXM9MTAwLjY0LjI1MC4yNTR+NTg0MDV+MTtsaW5lPW8yMDdkZXFtIi8+CiAgICA8L2xvY2FsPgogIDwvZGlhbG9nPgo8L2RpYWxvZy1pbmZvPgo="
}, "received_time" : 1439906398, "priority" : 0, "expires" : 1439906639 }
2(3748) DEBUG: presence [presentity.c:104]: publ_send200ok(): send 200OK
reply
2(3748) DEBUG: presence [presentity.c:105]: publ_send200ok(): etag=
a.1439906263.3748.6.0 - len= 21
2(3748) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac77d88
2(3748) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
2(3748) DEBUG: <core> [msg_translator.c:158]: check_via_address():
(10.0.20.100, 10.0.20.100, 0)
2(3748) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize():
WARNING:vqm_resize: resize(0) called
2(3748) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
2(3748) DEBUG: tm [t_reply.c:647]: _reply_light(): DEBUG: reply sent out.
buf=0x7fee4d90d2c0: SIP/2.0 200 OK
Reco..., shmem=0x7fee3ac7da48: SIP/2.0 200 OK
Reco
2(3748) DEBUG: tm [t_reply.c:657]: _reply_light(): DEBUG: _reply_light:
finished
2(3748) DEBUG: sl [sl.c:272]: send_reply(): reply in stateful mode (tm)
2(3748) DEBUG: presence [notify.c:1007]: get_subs_db(): querying database
table = active_watchers
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query(): query
to collection [active_watchers]
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query(): query
filter: { "presentity_uri" : "sip:302 at teste.teste.com.pt", "event" :
"dialog", "status" : 1, "contact" : { "$ne" : "" } }
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
columns filter: { "to_user" : 1, "to_domain" : 1, "from_user" : 1,
"from_domain" : 1, "watcher_username" : 1, "watcher_domain" : 1, "event_id"
: 1, "from_tag" : 1, "to_tag" : 1, "callid" : 1, "local_cseq" : 1,
"record_route" : 1, "contact" : 1, "expires" : 1, "reason" : 1,
"socket_info" : 1, "local_contact" : 1, "version" : 1 }
2(3748) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
for result set at 0x7fee4d90c5d8
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:349]: db_mongodb_get_columns():
18 columns returned from the query
2(3748) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 144
bytes for result names at 0x7fee4d8fbbe8
2(3748) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 72
bytes for result types at 0x7fee4d90cee0
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[0] named: to_user
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[0] at 0x7fee4d90cc88
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90cc88)[0]=[to_user] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[1] named: to_domain
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[1] at 0x7fee4d90d048
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90d048)[1]=[to_domain] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[2] named: from_user
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[2] at 0x7fee4d8fbdf8
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d8fbdf8)[2]=[from_user] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[3] named: from_domain
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[3] at 0x7fee4d8fbb70
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d8fbb70)[3]=[from_domain] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[4] named: watcher_username
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[4] at 0x7fee4d90d0f8
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90d0f8)[4]=[watcher_username] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[5] named: watcher_domain
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[5] at 0x7fee4d90bdc0
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90bdc0)[5]=[watcher_domain] (2)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[6] named: event_id
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[6] at 0x7fee4d90bd48
2(3748) INFO: db_mongodb [mongodb_dbase.c:454]: db_mongodb_get_columns():
unhandled data type column (event_id) type id (10), use DB1_STRING as
default
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90bd48)[6]=[event_id] (10)
2(3748) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[7] named: from_tag
2(3748) ERROR: db_mongodb [mongodb_dbase.c:381]: db_mongodb_get_columns():
field [from_tag] not found in result iterator
2(3748) ERROR: db_mongodb [mongodb_dbase.c:739]:
db_mongodb_store_result(): failed to set the columns
2(3748) ERROR: db_mongodb [mongodb_dbase.c:918]: db_mongodb_query():
failed to store result
2(3748) ERROR: db_mongodb [mongodb_dbase.c:927]: db_mongodb_query():
failed to do the query
2(3748) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 18 columns
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[0] at 0x7fee4d90cc88
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[1] at 0x7fee4d90d048
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[2] at 0x7fee4d8fbdf8
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[3] at 0x7fee4d8fbb70
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[4] at 0x7fee4d90d0f8
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[5] at 0x7fee4d90bdc0
2(3748) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[6] at 0x7fee4d90bd48
2(3748) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
names at 0x7fee4d8fbbe8
2(3748) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
types at 0x7fee4d90cee0
2(3748) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result set
at 0x7fee4d90c5d8
2(3748) ERROR: presence [notify.c:1065]: get_subs_db(): while querying
database
2(3748) ERROR: presence [notify.c:1191]: get_subs_dialog(): getting
dialogs from database
2(3748) DEBUG: presence [notify.c:1252]: publ_notify(): Could not find
subs_dialog
2(3748) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac77d88
2(3748) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
2(3748) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
2(3748) DEBUG: <core> [timer.c:574]: timer_add_safe(): timer_add called on
an active timer 0x7fee3ac77e08 (0x7fee3aa24948, 0x7fee3ac80f50), flags 201
2(3748) DEBUG: tm [t_funcs.c:148]: put_on_wait(): tm: put_on_wait:
transaction 0x7fee3ac77d88 already on wait
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
2(3748) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp
list (nil)
2(3748) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up
4(3750) DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request:
4(3750) DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method:
<PUBLISH>
4(3750) DEBUG: <core> [parser/msg_parser.c:610]: parse_msg(): uri: <
sip:301 at teste.teste.com.pt>
4(3750) DEBUG: <core> [parser/msg_parser.c:612]: parse_msg(): version:
<SIP/2.0>
4(3750) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bKe6c5.0f136ca6be0f5c28b3a23e84bd6bb28b.0>; state=16
4(3750) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
4(3750) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=2
4(3750) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers():
parse_headers: this is the first via
4(3750) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg...
4(3750) DEBUG: <core> [receive.c:177]: receive_msg(): preparing to run
routing scripts...
4(3750) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bKe6c5.cdc87860000000000000000000000000.0>; state=16
4(3750) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
4(3750) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=100
4(3750) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers():
parse_headers: this is the second via
4(3750) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec():
end of header reached, state=10
4(3750) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [33]; uri=[sip:301 at teste.teste.com.pt]
4(3750) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG:
to body [<sip:301 at teste.teste.com.pt>
]
4(3750) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
4(3750) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=669
4(3750) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 69
4(3750) DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg
id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
4(3750) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end
of header
4(3750) DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request:
start searching: hash=23662, isACK=0
4(3750) DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261
transaction matching failed
4(3750) DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
4(3750) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
c18f689913606b0287299bd41281c5e5
4(3750) INFO: <script>: Handling publish request - R=
sip:301 at teste.teste.com.pt ID=6869437916cdc134-3714 at 10.0.20.100
4(3750) DEBUG: presence [event_list.c:348]: search_event(): start event=
[dialog/5]
4(3750) DEBUG: presence [publish.c:316]: handle_publish(): SIP-If-Match
header not found
4(3750) DEBUG: presence [presentity.c:87]: generate_ETag(): etag=
a.1439906263.3750.6.0 / 21
4(3750) DEBUG: presence [publish.c:325]: handle_publish(): new etag =
a.1439906263.3750.6.0
4(3750) DEBUG: presence [publish.c:350]: handle_publish(): Expires header
found, value= 11
4(3750) DEBUG: presence [presentity.c:429]: update_presentity(): inserting
9 cols into table
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:1030]: db_mongodb_insert():
insert document: { "domain" : "teste.teste.com.pt", "username" : "301",
"event" : "dialog", "etag" : "a.1439906263.3750.6.0", "sender" : "", "body"
: { "$type" : "00", "$binary" :
"PD94bWwgdmVyc2lvbj0iMS4wIj8+CjxkaWFsb2ctaW5mbyB4bWxucz0idXJuOmlldGY6cGFyYW1zOnhtbDpuczpkaWFsb2ctaW5mbyIgdmVyc2lvbj0iMCIgc3RhdGU9ImZ1bGwiIGVudGl0eT0ic2lwOjMwMUB0ZXN0ZS5pdGNlbnRlci5jb20ucHQiPgogIDxkaWFsb2cgaWQ9IjMxMzQzMzM5MzkzMDM2MzIzNzM0MzQzMjMwMzkzMS02bnZ1eDRpYWZrenIiIGNhbGwtaWQ9IjMxMzQzMzM5MzkzMDM2MzIzNzM0MzQzMjMwMzkzMS02bnZ1eDRpYWZrenIiIGRpcmVjdGlvbj0iaW5pdGlhdG9yIj4KICAgIDxzdGF0ZT50ZXJtaW5hdGVkPC9zdGF0ZT4KICAgIDxyZW1vdGU+CiAgICAgIDxpZGVudGl0eT5zaXA6MzAyQHRlc3RlLml0Y2VudGVyLmNvbS5wdDt1c2VyPXBob25lPC9pZGVudGl0eT4KICAgICAgPHRhcmdldCB1cmk9InNpcDozMDJAdGVzdGUuaXRjZW50ZXIuY29tLnB0O3VzZXI9cGhvbmUiLz4KICAgIDwvcmVtb3RlPgogICAgPGxvY2FsPgogICAgICA8aWRlbnRpdHk+c2lwOjMwMUB0ZXN0ZS5pdGNlbnRlci5jb20ucHQ8L2lkZW50aXR5PgogICAgICA8dGFyZ2V0IHVyaT0ic2lwOjMwMUAxOTIuMTY4LjMwLjEwNzo1MDYwO2FsaWFzPTEwMC42NC4yNTAuMjU0fjU2NzEwfjE7bGluZT05YWp2NTQzOSIvPgogICAgPC9sb2NhbD4KICA8L2RpYWxvZz4KPC9kaWFsb2ctaW5mbz4K"
}, "received_time" : 1439906400, "priority" : 0, "expires" : 1439906411 }
4(3750) DEBUG: presence [presentity.c:104]: publ_send200ok(): send 200OK
reply
4(3750) DEBUG: presence [presentity.c:105]: publ_send200ok(): etag=
a.1439906263.3750.6.0 - len= 21
4(3750) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac7de60
4(3750) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
4(3750) DEBUG: <core> [msg_translator.c:158]: check_via_address():
(10.0.20.100, 10.0.20.100, 0)
4(3750) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize():
WARNING:vqm_resize: resize(0) called
4(3750) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
4(3750) DEBUG: tm [t_reply.c:647]: _reply_light(): DEBUG: reply sent out.
buf=0x7fee4d90c7f0: SIP/2.0 200 OK
Reco..., shmem=0x7fee3ac7a9d8: SIP/2.0 200 OK
Reco
4(3750) DEBUG: tm [t_reply.c:657]: _reply_light(): DEBUG: _reply_light:
finished
4(3750) DEBUG: sl [sl.c:272]: send_reply(): reply in stateful mode (tm)
4(3750) DEBUG: presence [notify.c:1007]: get_subs_db(): querying database
table = active_watchers
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query(): query
to collection [active_watchers]
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query(): query
filter: { "presentity_uri" : "sip:301 at teste.teste.com.pt", "event" :
"dialog", "status" : 1, "contact" : { "$ne" : "" } }
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
columns filter: { "to_user" : 1, "to_domain" : 1, "from_user" : 1,
"from_domain" : 1, "watcher_username" : 1, "watcher_domain" : 1, "event_id"
: 1, "from_tag" : 1, "to_tag" : 1, "callid" : 1, "local_cseq" : 1,
"record_route" : 1, "contact" : 1, "expires" : 1, "reason" : 1,
"socket_info" : 1, "local_contact" : 1, "version" : 1 }
4(3750) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
for result set at 0x7fee4d90cda8
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:349]: db_mongodb_get_columns():
18 columns returned from the query
4(3750) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 144
bytes for result names at 0x7fee4d8fbe38
4(3750) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 72
bytes for result types at 0x7fee4d90cd08
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[0] named: to_user
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[0] at 0x7fee4d90cfd0
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90cfd0)[0]=[to_user] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[1] named: to_domain
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[1] at 0x7fee4d90d018
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90d018)[1]=[to_domain] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[2] named: from_user
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[2] at 0x7fee4d90ccc0
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90ccc0)[2]=[from_user] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[3] named: from_domain
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[3] at 0x7fee4d90ce18
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90ce18)[3]=[from_domain] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[4] named: watcher_username
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[4] at 0x7fee4d90bb80
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90bb80)[4]=[watcher_username] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[5] named: watcher_domain
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[5] at 0x7fee4d90bd90
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:431]: db_mongodb_get_columns():
use DB1_STRING result type
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90bd90)[5]=[watcher_domain] (2)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[6] named: event_id
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[6] at 0x7fee4d90be08
4(3750) INFO: db_mongodb [mongodb_dbase.c:454]: db_mongodb_get_columns():
unhandled data type column (event_id) type id (10), use DB1_STRING as
default
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90be08)[6]=[event_id] (10)
4(3750) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[7] named: from_tag
4(3750) ERROR: db_mongodb [mongodb_dbase.c:381]: db_mongodb_get_columns():
field [from_tag] not found in result iterator
4(3750) ERROR: db_mongodb [mongodb_dbase.c:739]:
db_mongodb_store_result(): failed to set the columns
4(3750) ERROR: db_mongodb [mongodb_dbase.c:918]: db_mongodb_query():
failed to store result
4(3750) ERROR: db_mongodb [mongodb_dbase.c:927]: db_mongodb_query():
failed to do the query
4(3750) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 18 columns
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[0] at 0x7fee4d90cfd0
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[1] at 0x7fee4d90d018
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[2] at 0x7fee4d90ccc0
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[3] at 0x7fee4d90ce18
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[4] at 0x7fee4d90bb80
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[5] at 0x7fee4d90bd90
4(3750) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[6] at 0x7fee4d90be08
4(3750) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
names at 0x7fee4d8fbe38
4(3750) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
types at 0x7fee4d90cd08
4(3750) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result set
at 0x7fee4d90cda8
4(3750) ERROR: presence [notify.c:1065]: get_subs_db(): while querying
database
4(3750) ERROR: presence [notify.c:1191]: get_subs_dialog(): getting
dialogs from database
4(3750) DEBUG: presence [notify.c:1252]: publ_notify(): Could not find
subs_dialog
4(3750) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac7de60
4(3750) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
4(3750) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
4(3750) DEBUG: <core> [timer.c:574]: timer_add_safe(): timer_add called on
an active timer 0x7fee3ac7dee0 (0x7fee3aa24bb8, 0x7fee3aa24bb8), flags 201
4(3750) DEBUG: tm [t_funcs.c:148]: put_on_wait(): tm: put_on_wait:
transaction 0x7fee3ac7de60 already on wait
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list
(nil)
4(3750) DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp
list (nil)
4(3750) DEBUG: <core> [receive.c:278]: receive_msg(): cleaning up
3(3749) DEBUG: <core> [parser/msg_parser.c:606]: parse_msg(): SIP Request:
3(3749) DEBUG: <core> [parser/msg_parser.c:608]: parse_msg(): method:
<PUBLISH>
3(3749) DEBUG: <core> [parser/msg_parser.c:610]: parse_msg(): uri: <
sip:302 at teste.teste.com.pt;user=phone>
3(3749) DEBUG: <core> [parser/msg_parser.c:612]: parse_msg(): version:
<SIP/2.0>
3(3749) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bKf6c5.0bdcb68b39d9eb5935258276fd47d068.0>; state=16
3(3749) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
3(3749) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=2
3(3749) DEBUG: <core> [parser/msg_parser.c:498]: parse_headers():
parse_headers: this is the first via
3(3749) DEBUG: <core> [receive.c:134]: receive_msg(): After parse_msg...
3(3749) DEBUG: <core> [receive.c:177]: receive_msg(): preparing to run
routing scripts...
3(3749) DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bKf6c5.26f01f40000000000000000000000000.0>; state=16
3(3749) DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of
header reached, state=5
3(3749) DEBUG: <core> [parser/msg_parser.c:496]: parse_headers():
parse_headers: Via found, flags=100
3(3749) DEBUG: <core> [parser/msg_parser.c:509]: parse_headers():
parse_headers: this is the second via
3(3749) DEBUG: <core> [parser/parse_addr_spec.c:894]: parse_addr_spec():
end of header reached, state=10
3(3749) DEBUG: <core> [parser/msg_parser.c:173]: get_hdr_field(): DEBUG:
get_hdr_field: <To> [44]; uri=[sip:302 at teste.teste.com.pt;user=phone]
3(3749) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG:
to body [<sip:302 at teste.teste.com.pt;user=phone>
]
3(3749) DEBUG: <core> [parser/msg_parser.c:153]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
3(3749) DEBUG: <core> [parser/msg_parser.c:187]: get_hdr_field(): DEBUG:
get_hdr_body : content_length=680
3(3749) DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 69
3(3749) DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg
id=6 , global msg id=5 , T on entrance=0xffffffffffffffff
3(3749) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2():
beginning of SIP-If-Match: yet=0x2d706973
3(3749) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2(): middle
of SIP-If-Match: yet=0x6d2d6669
3(3749) DEBUG: <core> [parser/parse_hname2.c:177]: parse_hname2(): end of
SIP-If-Match
3(3749) DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end
of header
3(3749) DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request:
start searching: hash=23663, isACK=0
3(3749) DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261
transaction matching failed
3(3749) DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
3(3749) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
5cfad5206cd64562ba87bb365d5c370a
3(3749) INFO: <script>: Handling publish request - R=
sip:302 at teste.teste.com.pt;user=phone ID=6869437916cdc135-3714 at 10.0.20.100
3(3749) DEBUG: presence [event_list.c:348]: search_event(): start event=
[dialog/5]
3(3749) DEBUG: presence [publish.c:329]: handle_publish(): SIP-If-Match
header found
3(3749) DEBUG: presence [publish.c:338]: handle_publish(): existing etag
= a.1439906263.3748.6.0
3(3749) DEBUG: presence [publish.c:350]: handle_publish(): Expires header
found, value= 11
3(3749) DEBUG: presence [presentity.c:87]: generate_ETag(): etag=
a.1439906263.3749.6.1 / 21
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query():
query to collection [presentity]
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query(): query
filter: { "domain" : "teste.teste.com.pt", "username" : "302", "event" :
"dialog", "etag" : "a.1439906263.3748.6.0" }
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
columns filter: { "body" : 1, "sender" : 1 }
3(3749) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
for result set at 0x7fee4d90cda8
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:349]: db_mongodb_get_columns():
2 columns returned from the query
3(3749) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 16
bytes for result names at 0x7fee4d90ccc0
3(3749) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 8
bytes for result types at 0x7fee4d8f4270
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[0] named: body
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:396]: db_mongodb_get_columns():
allocate 16 bytes for RES_NAMES[0] at 0x7fee4d90d018
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:426]: db_mongodb_get_columns():
use DB1_BLOB result type
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:460]: db_mongodb_get_columns():
RES_NAMES(0x7fee4d90d018)[0]=[body] (5)
3(3749) DEBUG: db_mongodb [mongodb_dbase.c:377]: db_mongodb_get_columns():
Found a field[1] named: sender
3(3749) ERROR: db_mongodb [mongodb_dbase.c:381]: db_mongodb_get_columns():
field [sender] not found in result iterator
3(3749) ERROR: db_mongodb [mongodb_dbase.c:739]:
db_mongodb_store_result(): failed to set the columns
3(3749) ERROR: db_mongodb [mongodb_dbase.c:918]: db_mongodb_query():
failed to store result
3(3749) ERROR: db_mongodb [mongodb_dbase.c:927]: db_mongodb_query():
failed to do the query
3(3749) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 2 columns
3(3749) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
RES_NAMES[0] at 0x7fee4d90d018
3(3749) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
names at 0x7fee4d90ccc0
3(3749) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
types at 0x7fee4d8f4270
3(3749) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result set
at 0x7fee4d90cda8
3(3749) ERROR: presence [presentity.c:757]: update_presentity():
unsuccessful sql query
3(3749) ERROR: presence [publish.c:462]: handle_publish(): when updating
presentity
3(3749) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac7adf8
3(3749) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T
already found!
3(3749) DEBUG: <core> [msg_translator.c:158]: check_via_address():
(10.0.20.100, 10.0.20.100, 0)
3(3749) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize():
WARNING:vqm_resize: resize(0) called
3(3749) DEBUG: tm [t_reply.c:1589]: cleanup_uac_timers(): DEBUG:
cleanup_uac_timers: RETR/FR timers reset
3(3749) DEBUG: tm [t_reply.c:647]: _reply_light(): DEBUG: reply sent out.
buf=0x7fee4d90d450: SIP/2.0 500 Server I..., shmem=0x7fee3ac80ab0: SIP/2.0
500 Server I
3(3749) DEBUG: tm [t_reply.c:657]: _reply_light(): DEBUG: _reply_light:
finished
3(3749) DEBUG: sl [sl.c:272]: send_reply(): reply in stateful mode (tm)
3(3749) ERROR: <script>: Failed to handle publish request - R=
sip:302 at teste.teste.com.pt;user=phone ID=6869437916cdc135-3714 at 10.0.20.100
3(3749) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg:
msg id=6 global id=6 T start=0x7fee3ac7adf8
Best Regards
José Seabra
2015-08-18 14:26 GMT+01:00 José Seabra <joseseabra4 at gmail.com>:
> Hello,
>
> It is working now, so summarizing about what we need to do in mongodb to
> kamailio starts up is:
>
> Access to Mongodb cli
>
> Create databases kamailio
>
> > use kamailio
> switched to db kamailio
> >
> > db
> kamailio
>
>
> create collection named version
>
> > db.createCollection("version")
> > show collections
> system.indexes
> version
> >
>
> Add the records for the tables version
>
> > db.getCollection("version").insert({table_name: "presentity",
> table_version: NumberInt(4) })
> WriteResult({ "nInserted" : 1 })
>
> > db.getCollection("version").insert({table_name: "watchers",
> table_version: NumberInt(3) })
> WriteResult({ "nInserted" : 1 })
>
> db.getCollection("version").insert({table_name: "active_watchers",
> table_version: NumberInt(11) })
> WriteResult({ "nInserted" : 1 })
>
> Thank you for your help
> Best Regards
> José Seabra
>
> 2015-08-18 13:10 GMT+01:00 Daniel-Constantin Mierla <miconda at gmail.com>:
>
>> Hello,
>>
>> if I remember correctly, the default type for numbers is float/double.
>> You have to use a special form/function in mongo client when inserting a
>> record to force the type of the value to be integer.
>>
>> Perhaps searching on the web of how to insert an integer value in mongodb
>> will give you the proper hings.
>>
>> Cheers,
>> Daniel
>>
>> On 18/08/15 13:17, José Seabra wrote:
>>
>> Hi,
>> Well i didn't noticed before, but after create a document in mongodb the
>> error that kamailio gives now is different but it still related with table
>> version check.
>>
>> Seems that kamailio can query the document successfully and get the
>> table_version field.
>>
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:671]:
>> db_mongodb_convert_result(): selected document: { "_id" : { "$oid" :
>> "55d2fc84b04c015195aee4b2" }, "table_version" : 4 }
>> 0(3068) DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32
>> bytes for row values at 0x7fe6fee76390
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:522]:
>> db_mongodb_convert_bson(): looking for field[0] named: table_version
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:610]:
>> db_mongodb_convert_bson(): RES_NAMES(0x7fe6fee72490)[0]=[table_version] (1)
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:682]:
>> db_mongodb_convert_result(): retrieved number of rows: 1
>> *0(3068) ERROR: <core> [db.c:414]: db_table_version(): invalid type (2)
>> or nul (0) version columns for presentity*
>>
>>
>>
>> ALL Log:
>>
>> Listening on
>> udp: 10.0.20.100:5080
>> Aliases:
>>
>> 0(3066) DEBUG: <core> [cfg/cfg.c:176]: cfg_declare(): DEBUG:
>> register_cfg_def(): new config group has been registered: 'core' (num=50,
>> size=200)
>> 0(3066) DEBUG: <core> [cfg/cfg.c:176]: cfg_declare(): DEBUG:
>> register_cfg_def(): new config group has been registered: 'tcp' (num=26,
>> size=104)
>> 0(3066) DEBUG: <core> [timer.c:255]: init_timer(): starting with
>> *ticks=1210106959
>> 0(3066) DEBUG: <core> [timer.c:297]: init_timer(): timer_list between
>> 0x7fe6ebf85728 and 0x7fe6ebfc9728
>> 0(3066) INFO: <core> [tcp_main.c:4656]: init_tcp(): using epoll_lt as
>> the io watch method (auto detected)
>> 0(3068) DEBUG: <core> [daemonize.c:207]: enable_dumpable(): trying
>> enable core dumping...
>> 0(3068) DEBUG: <core> [daemonize.c:225]: enable_dumpable(): core dumping
>> is enabled now (1)...
>> 0(3068) DEBUG: <core> [daemonize.c:583]: set_core_dump(): core dump
>> limits set to 18446744073709551615
>> 0(3068) DEBUG: <core> [async_task.c:88]: async_task_init(): start
>> initializing asynk task framework
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): db_text
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): db_mysql
>> 0(3068) DEBUG: db_mysql [km_db_mysql.c:86]: kam_mysql_mod_init(): MySQL
>> client version is 5.1.73
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): db_mongodb
>> 0(3068) DEBUG: db_mongodb [db_mongodb_mod.c:98]: mod_init(): module
>> initializing
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): sl
>> 0(3068) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
>> f452807bca511b98621cbbe6e749d8ef
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <load_tm> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) ERROR: tm [tm_load.c:37]: load_tm(): tm:load_tm: Module not
>> initialized yet, make sure that all modules that need tm module are loaded
>> after tm in the configuration file
>> 0(3068) INFO: sl [sl.c:157]: mod_init(): could not bind tm module - only
>> stateless mode available during modules initialization
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): maxfwd
>> 0(3068) DEBUG: <core> [cfg/cfg.c:176]: cfg_declare(): DEBUG:
>> register_cfg_def(): new config group has been registered: 'maxfwd' (num=1,
>> size=4)
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): textops
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): tm
>> 0(3068) DEBUG: tm [tm.c:756]: mod_init(): TM - (sizeof cell=488,
>> sip_msg=1768) initializing...
>> 0(3068) DEBUG: tm [callid.c:101]: init_callid(): Call-ID initialization:
>> '76bf762544f60619'
>> 0(3068) DEBUG: tm [lock.c:74]: lock_initialize(): DEBUG:
>> lock_initialize: lock initialization started
>> 0(3068) DEBUG: tm [timer.c:199]: tm_init_timers(): tm: tm_init_timers:
>> fr=480 fr_inv=1920 wait=80 delete=4 t1=500 t2=4000 max_inv_lifetime=2880
>> max_noninv_lifetime=512
>> 0(3068) DEBUG: <core> [cfg/cfg.c:176]: cfg_declare(): DEBUG:
>> register_cfg_def(): new config group has been registered: 'tm' (num=36,
>> size=168)
>> 0(3068) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
>> eabd4dc455c32eca91da2be9405373ce
>> 0(3068) DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated:
>> 176231eb72a239b3e7f931a1ef6c4100
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): rr
>> 0(3068) DEBUG: <core> [sr_module.c:678]: find_mod_export_record():
>> find_export_record: <bind_ob> not found
>> 0(3068) INFO: rr [../outbound/api.h:54]: ob_load_api(): Failed to import
>> bind_ob
>> 0(3068) INFO: rr [rr_mod.c:174]: mod_init(): outbound module not
>> available
>> 0(3068) DEBUG: <core> [sr_module.c:942]: init_mod(): presence
>> 0(3068) DEBUG: presence [presence.c:274]: mod_init():
>> db_url=mongodb://localhost/kamailio/28/0x7fe6fee55608
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <bind_sl> in module sl
>> [/usr/local/lib64/kamailio/modules/sl.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <load_tm> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_newtran> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_relay_to_tcp> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_relay_to_udp> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_relay> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_forward_nonack> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <t_release> in module tm
>> [/usr/local/lib64/kamailio/modules/tm.so]
>> 0(3068) DEBUG: <core> [sr_module.c:672]: find_mod_export_record():
>> find_export_record: found <db_bind_api> in module db_mongodb
>> [/usr/local/lib64/kamailio/modules/db_mongodb.so]
>> 0(3068) DEBUG: <core> [db.c:205]: db_bind_mod(): using db bind api for
>> db_mongodb
>> 0(3068) DEBUG: <core> [db.c:310]: db_do_init2(): connection
>> 0x7fe6fee72190 not found in pool
>> 0(3068) DEBUG: db_mongodb [mongodb_connection.c:55]:
>> db_mongodb_new_connection(): connection open to:
>> mongodb://localhost/kamailio
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:851]: db_mongodb_query():
>> query to collection [version]
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:885]: db_mongodb_query():
>> query filter: { "table_name" : "presentity" }
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:904]: db_mongodb_query():
>> columns filter: { "table_version" : 1 }
>> 0(3068) DEBUG: <core> [db_res.c:116]: db_new_result(): allocate 56 bytes
>> for result set at 0x7fe6fee72338
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:349]:
>> db_mongodb_get_columns(): 1 columns returned from the query
>> 0(3068) DEBUG: <core> [db_res.c:154]: db_allocate_columns(): allocate 8
>> bytes for result names at 0x7fe6fee72410
>> 0(3068) DEBUG: <core> [db_res.c:165]: db_allocate_columns(): allocate 4
>> bytes for result types at 0x7fe6fee72450
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:377]:
>> db_mongodb_get_columns(): Found a field[0] named: table_version
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:396]:
>> db_mongodb_get_columns(): allocate 16 bytes for RES_NAMES[0] at
>> 0x7fe6fee72490
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:416]:
>> db_mongodb_get_columns(): use DB1_DOUBLE result type
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:460]:
>> db_mongodb_get_columns(): RES_NAMES(0x7fe6fee72490)[0]=[table_version] (1)
>> 0(3068) DEBUG: <core> [db_res.c:184]: db_allocate_rows(): allocate 16000
>> bytes for rows at 0x7fe6fee724d8
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:671]:
>> db_mongodb_convert_result(): selected document: { "_id" : { "$oid" :
>> "55d2fc84b04c015195aee4b2" }, "table_version" : 4 }
>> 0(3068) DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32
>> bytes for row values at 0x7fe6fee76390
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:522]:
>> db_mongodb_convert_bson(): looking for field[0] named: table_version
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:610]:
>> db_mongodb_convert_bson(): RES_NAMES(0x7fe6fee72490)[0]=[table_version] (1)
>> 0(3068) DEBUG: db_mongodb [mongodb_dbase.c:682]:
>> db_mongodb_convert_result(): retrieved number of rows: 1
>> 0(3068) ERROR: <core> [db.c:414]: db_table_version(): invalid type (2)
>> or nul (0) version columns for presentity
>> 0(3068) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 1 columns
>> 0(3068) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing
>> RES_NAMES[0] at 0x7fe6fee72490
>> 0(3068) DEBUG: <core> [db_res.c:92]: db_free_columns(): freeing result
>> names at 0x7fe6fee72410
>> 0(3068) DEBUG: <core> [db_res.c:97]: db_free_columns(): freeing result
>> types at 0x7fe6fee72450
>> 0(3068) DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows
>> 0(3068) DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values
>> at 0x7fe6fee76390
>> 0(3068) DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at
>> 0x7fe6fee724d8
>> 0(3068) DEBUG: <core> [db_res.c:134]: db_free_result(): freeing result
>> set at 0x7fe6fee72338
>> 0(3068) ERROR: <core> [db.c:432]: db_check_table_version(): querying
>> version for table presentity
>> * 0(3068) ERROR: presence [presence.c:358]: mod_init(): error during
>> table version check*
>> * 0(3068) ERROR: <core> [sr_module.c:945]: init_mod(): Error while
>> initializing module presence
>> (/usr/local/lib64/kamailio/modules/presence.so)*
>> ERROR: error while initializing modules
>> 0(3068) DEBUG: <core> [db_pool.c:100]: pool_remove(): removing
>> connection from the pool
>> 0(3068) DEBUG: tm [t_funcs.c:86]: tm_shutdown(): DEBUG: tm_shutdown :
>> start
>> 0(3068) DEBUG: tm [t_funcs.c:89]: tm_shutdown(): DEBUG: tm_shutdown :
>> emptying hash table
>> 0(3068) DEBUG: tm [t_funcs.c:91]: tm_shutdown(): DEBUG: tm_shutdown :
>> removing semaphores
>> 0(3068) DEBUG: tm [t_funcs.c:93]: tm_shutdown(): DEBUG: tm_shutdown :
>> destroying tmcb lists
>> 0(3068) DEBUG: tm [t_funcs.c:96]: tm_shutdown(): DEBUG: tm_shutdown :
>> done
>> 0(3068) DEBUG: db_text [dbtext.c:106]: destroy(): destroy ...
>> 0(3068) INFO: <core> [sctp_core.c:53]: sctp_core_destroy(): SCTP API not
>> initialized
>> 0(3068) DEBUG: <core> [mem/shm_mem.c:232]: shm_mem_destroy():
>> shm_mem_destroy
>> 0(3068) DEBUG: <core> [mem/shm_mem.c:235]: shm_mem_destroy(): destroying
>> the shared memory lock
>>
>>
>> Best regards
>>
>>
>> --
>> Daniel-Constantin Mierlahttp://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
>> Book: SIP Routing With Kamailio - http://www.asipto.com
>>
>>
>
>
> --
> Cumprimentos
> José Seabra
>
--
Cumprimentos
José Seabra
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20150818/0d91cbe8/attachment.html>
More information about the sr-users
mailing list