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@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@teste.teste.com.pt] 
 3(3749) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [<sip:301@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@teste.teste.com.pt ID=6869437916cdc134-3693@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@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@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@teste.teste.com.pt] 
 1(3747) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [<sip:301@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@teste.teste.com.pt ID=6869437916cdc139-3695@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@teste.teste.com.pt ID=6869437916cdc139-3695@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@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@teste.teste.com.pt;user=phone] 
 2(3748) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [<sip:302@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@teste.teste.com.pt;user=phone ID=6869437916cdc13a-3695@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@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@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@teste.teste.com.pt] 
 4(3750) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [<sip:301@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@teste.teste.com.pt ID=6869437916cdc134-3714@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@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@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@teste.teste.com.pt;user=phone] 
 3(3749) DEBUG: <core> [parser/msg_parser.c:175]: get_hdr_field(): DEBUG: to body [<sip:302@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@teste.teste.com.pt;user=phone ID=6869437916cdc135-3714@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@teste.teste.com.pt;user=phone ID=6869437916cdc135-3714@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@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@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 Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Book: SIP Routing With Kamailio - http://www.asipto.com



--
Cumprimentos
José Seabra



--
Cumprimentos
José Seabra