Z6kLGXcc

1Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg: SIP Request:
2Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  method:  <INVITE>
3Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.203>
4Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  version: <SIP/2.0>
5Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=2
6Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
7Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=10
8Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
9Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: <To> [27]; uri=[sip:1002@192.168.56.203]
10Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>#015#012]
11Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537>; state=16
12Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: end of header reached, state=5
13Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: via found, flags=2
14Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: this is the first via
15Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: After parse_msg...
16Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: preparing to run routing scripts...
17Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=100
18Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:maxfwd:is_maxfwd_present: value = 70
19Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:uri:has_totag: no totag
20Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=78
21Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: start searching: hash=45572, isACK=0
22Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:matching_3261: RFC3261 transaction matching failed
23Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: no transaction found
24Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=423a329a
25Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
26Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
27Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
28Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
29Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
30Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=200
31Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: content_length=949
32Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: found end of header
33Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:rr:find_first_route: No Route headers found
34Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:rr:loose_route: There is no Route HF
35Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
36Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
37Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
38Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:registrar:parse_lookup_flags: final flags: 1
39Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:registrar:select_contacts: ct: sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203
40Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:registrar:push_branch: setting as ruri <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
41Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_get_ctx: new ctx=0x7f983a5cda98
42Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key GetMaxUsage
43Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 11 GetMaxUsage in 0x7f983a5cdb90
44Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key GetAttributes
45Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 13 GetAttributes in 0x7f983a5cdb90
46Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key GetSuppliers
47Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 12 GetSuppliers in 0x7f983a5cdb90
48Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key AuthorizeResources
49Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 18 AuthorizeResources in 0x7f983a5cdb90
50Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key ProcessThresholds
51Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 17 ProcessThresholds in 0x7f983a5cdb90
52Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key ProcessStatQueues
53Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 17 ProcessStatQueues in 0x7f983a5cdb90
54Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_real_kv: created new key RequestType
55Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:pv_set_cgr: add cgr kv: 11 RequestType in 0x7f983a5cdb90
56Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_newtran: transaction on entrance=(nil)
57Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
58Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=78
59Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: start searching: hash=45572, isACK=0
60Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:matching_3261: RFC3261 transaction matching failed
61Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: no transaction found
62Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:run_reqin_callbacks: trans=0x7f983a5ce110, callback type 1, id 1 entered
63Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_move_ctx: ctx=0x7f983a5cda98 moved in transaction
64Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:run_reqin_callbacks: trans=0x7f983a5ce110, callback type 1, id 0 entered
65Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
66Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:_shm_resize: resize(0) called
67Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:_reply_light: reply sent out. buf=0x7f983e3976d8: SIP/2.0 1..., shmem=0x7f983a5d2328: SIP/2.0 1
68Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:_reply_light: finished
69Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_handle_async_cmd: sending json string: { "method": "SessionSv1.AuthorizeEventWithDigest", "id": 657063430, "params": [ { "ProcessStatQueues": true, "ProcessThresholds": true, "AuthorizeResources": true, "GetSuppliers": true, "GetAttributes": true, "GetMaxUsage": true, "Event": { "RequestType": "*prepaid", "OriginID": "c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0", "Account": "1001", "SetupTime": "1524733418", "Destination": "1002" } } ] }
70Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_get_free_conn: no free connection - create a new one!
71Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384
72Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: trying : 32768
73Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: setting snd: set=32768,verify=65536
74Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: trying : 65536
75Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: setting snd: set=65536,verify=131072
76Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: trying : 131072
77Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: setting snd: set=131072,verify=262144
78Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: trying : 262144
79Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:probe_max_sock_buff: setting snd: set=262144,verify=425984
80Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
81Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 16
82Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrc_send: Successfully sent 407 bytes
83Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_handle_async: placing async job into reactor
84Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:io_watch_add: [UDP_worker] io_watch_add op (16 on 12) (0x823980, 16, 16, 0x7f983a5d2588,1), fd_no=4/13107
85Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
86Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: cleaning up
87Apr 26 05:03:38 teo CGRateS <64fbb36> [7616]: Threshold hit, Balance: {"ID":"cgrates.org:1001","BalanceMap":{"*monetary":[{"Uuid":"0f6f70ea-8d05-4102-ac6c-27f3d2009a80","ID":"","Value":10,"Directions":{"*out":true},"ExpirationDate":"0001-01-01T00:00:00Z","Weight":10,"DestinationIDs":{},"RatingSubject":"","Categories":{},"SharedGroups":{},"Timings":null,"TimingIDs":{},"Disabled":false,"Factor":null,"Blocker":false}]},"UnitCounters":null,"ActionTriggers":null,"AllowNegative":false,"Disabled":false}
88Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_resume_async: resuming on fd 16, transaction 0x7f983a5ce110
89Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrc_async_read: Event on fd 16 from 127.0.0.1:2014
90Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrc_async_read: Received (possible partial) json: {{"id":657063430,"result":{"AttributesDigest":null,"ResourceAllocation":"SPECIAL_1003","MaxUsage":5688,"SuppliersDigest":"supplier2,supplier1"},"error":null}#012}
91Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrates_process: Processing JSON-RPC: { "id": 657063430, "result": { "AttributesDigest": null, "ResourceAllocation": "SPECIAL_1003", "MaxUsage": 5688, "SuppliersDigest": "supplier2,supplier1" }, "error": null }
92Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrates_process: treating JSON-RPC as a reply
93Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrates_set_reply: new local ctx=0x7f983e397598
94Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgrates_set_reply: Setting reply to s={ "AttributesDigest": null, "ResourceAllocation": "SPECIAL_1003", "MaxUsage": 5688, "SuppliersDigest": "supplier2,supplier1" }
95Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_add_local: created new local key ResourceAllocation
96Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_add_local: created new local key MaxUsage
97Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_add_local: created new local key SuppliersDigest
98Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:io_watch_del: [UDP_worker] io_watch_del op on index -1 16 (0x823980, 16, -1, 0x0,0x1) fd_no=5 called
99Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:io_watch_add: [UDP_worker] io_watch_add op (16 on 12) (0x823980, 16, 2, 0x7f983a5d2630,1), fd_no=4/13107
100Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:comp_scriptvar: int 20 : 1 / 0
101Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:w_cgr_acc: engaging accounting for all branches!
102Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:build_new_dlg: new dialog 0x7f983a5d26a8 (c=c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0,f=sip:1001@192.168.56.203,t=sip:1002@192.168.56.203,ft=423a329a) on hash 461
103Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
104Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:init_leg_info: route_set , contact sip:1001@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203, cseq 1 and bind_addr udp:192.168.56.203:5060
105Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7f983a5d26a8: tag=<423a329a> rcseq=<0>
106Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:link_dlg: ref dlg 0x7f983a5d26a8 with 3 -> 3 in h_entry 0x7f983a570fe8 - 461
107Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:rr:add_rr_param: adding (;did=dc1.92af5555)
108Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:rr:add_rr_param: second RR lump found
109Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:rr:add_rr_param: second RR lump found
110Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_create_dialog: t hash_index = 45572, t label = 586131867
111Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_acc_ctx: new acc ctx=0x7f983a5d3560
112Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_new_acc_ctx: init ref=1 ctx=0x7f983a5d3560
113Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:new_dlg_val: inserting <cgrX_ctx>=<`5]:˜>
114Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_ref_acc_ctx: general ctx ref=2 ctx=0x7f983a5d3560
115Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:w_cgr_acc: session info tag= acc=1001 dst=1002 mask=FFFFFFFF
116Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_ref_acc_ctx: tm ref=3 ctx=0x7f983a5d3560
117Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:update_cloned_msg_from_msg: new_uri must be copied old=71, new=71
118Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: new branch at sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203
119Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 4, id 1 entered
120Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_update_contact: Updated dialog 0x7f983a5d26a8 contact to <sip:1001@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
121Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:core:mk_proxy: doing DNS lookup...
122Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:set_timer: relative timeout is 500000
123Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [4]: 0x7f983a5ce330 (266400000)
124Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [0]: 0x7f983a5ce360 (271)
125Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
126Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 2 in entry 0x7f983a570fe8
127Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:cgrates:_cgr_free_local_ctx: release local ctx=0x7f983e397598
128Apr 26 05:03:38 teo /usr/sbin/opensips[7490]: DBG:tm:clean_msg_clone: removing hdr->parsed 7
129Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg: SIP Reply  (status):
130Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  version: <SIP/2.0>
131Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  status:  <180>
132Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  reason:  <Ringing>
133Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=2
134Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
135Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=61c51e14
136Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
137Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
138Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1002@192.168.56.203]
139Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>]
140Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK402b.b99afe22.0>; state=9
141Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: next_via
142Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537>; state=16
143Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: end of header reached, state=5
144Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: via found, flags=2
145Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: this is the first via
146Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: After parse_msg...
147Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:forward_reply: found module tm, passing reply to it
148Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_check: start=0xffffffffffffffff
149Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=22
150Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=8
151Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: hash 45572 label 586131867 branch 0
152Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5ce110] after is 1
153Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5ce110)!
154Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_check: end=0x7f983a5ce110
155Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
156Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: incoming reply
157Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_should_relay_response: T_code=100, new_code=180
158Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:relay_reply: T_state=5, branch=0, save=0, relay=0, cancel_BM=0
159Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 8, id 0 entered
160Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:dialog:push_reply_in_dialog: 0x7f983a5d26a8 totag in rpl is <61c51e14> (8)
161Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:dialog:push_reply_in_dialog: new branch with tag <61c51e14>
162Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:dialog:init_leg_info: route_set , contact , cseq 1 and bind_addr udp:192.168.56.203:5060
163Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0x7f983a5d26a8: tag=<61c51e14> rcseq=<1>
164Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:build_res_buf_from_sip_res:  old size: 552, new size: 490
165Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:build_res_buf_from_sip_res: copied size: orig:260, new: 490, rest: 292 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 1 INVITE#015#012Call-ID: c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0#015#012From: "1001" <sip:1001@192.168.56.203>;tag=423a329a#015#012To: <sip:1002@192.168.56.203>;tag=61c51e14#015#012Via: SIP/2.0/UDP 192.168.56.1:5060;branch=z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537#015#012Record-Route: <sip:192.168.56.203;lr;did=dc1.92af5555>#015#012Contact: "1002" <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0
166Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 64, id 0 entered
167Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
168Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
169Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
170Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
171Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
172Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding int param
173Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding int param
174Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
175Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 1 to state 2, due event 2
176Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:relay_reply: sent buf=0x7f983e394d38: SIP/2.0 1..., shmem=0x7f983a5d1ee0: SIP/2.0 1
177Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 128, id 2 entered
178Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:cgrates:cgr_tmcb_func: Called callback for transaction 0x7f983a5ce110 type 128 reply_code=180 branch=0
179Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:reply_received: FR_INV_TIMER = 30
180Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:set_timer: relative timeout is 30
181Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:insert_timer_unsafe: [1]: 0x7f983a5ce360 (296)
182Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
183Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
184Apr 26 05:03:38 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: cleaning up
185Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg: SIP Reply  (status):
186Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  version: <SIP/2.0>
187Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  status:  <180>
188Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  reason:  <Ringing>
189Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=2
190Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
191Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=61c51e14
192Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
193Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
194Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1002@192.168.56.203]
195Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>]
196Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK402b.b99afe22.0>; state=9
197Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: next_via
198Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537>; state=16
199Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: end of header reached, state=5
200Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: via found, flags=2
201Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: this is the first via
202Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: After parse_msg...
203Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:forward_reply: found module tm, passing reply to it
204Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: start=0xffffffffffffffff
205Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=22
206Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=8
207Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: hash 45572 label 586131867 branch 0
208Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5ce110] after is 1
209Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5ce110)!
210Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: end=0x7f983a5ce110
211Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
212Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: incoming reply
213Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_should_relay_response: T_code=180, new_code=180
214Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: T_state=5, branch=0, save=0, relay=0, cancel_BM=0
215Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 8, id 0 entered
216Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: 0x7f983a5d26a8 totag in rpl is <61c51e14> (8)
217Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: branch with tag <61c51e14> already exists
218Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res:  old size: 552, new size: 490
219Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res: copied size: orig:260, new: 490, rest: 292 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 1 INVITE#015#012Call-ID: c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0#015#012From: "1001" <sip:1001@192.168.56.203>;tag=423a329a#015#012To: <sip:1002@192.168.56.203>;tag=61c51e14#015#012Via: SIP/2.0/UDP 192.168.56.1:5060;branch=z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537#015#012Record-Route: <sip:192.168.56.203;lr;did=dc1.92af5555>#015#012Contact: "1002" <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0
220Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 64, id 0 entered
221Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 2 to state 2, due event 2
222Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: sent buf=0x7f983e3945c8: SIP/2.0 1..., shmem=0x7f983a5d1ee0: SIP/2.0 1
223Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 128, id 2 entered
224Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_tmcb_func: Called callback for transaction 0x7f983a5ce110 type 128 reply_code=180 branch=0
225Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
226Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
227Apr 26 05:03:39 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: cleaning up
228Apr 26 05:03:39 teo /usr/sbin/opensips[7482]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f983a5ce330 next=(nil), timeout=266400000
229Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg: SIP Reply  (status):
230Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  version: <SIP/2.0>
231Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  status:  <180>
232Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  reason:  <Ringing>
233Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=2
234Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
235Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=61c51e14
236Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
237Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
238Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1002@192.168.56.203]
239Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>]
240Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK402b.b99afe22.0>; state=9
241Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: next_via
242Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537>; state=16
243Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: end of header reached, state=5
244Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: via found, flags=2
245Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: this is the first via
246Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: After parse_msg...
247Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:forward_reply: found module tm, passing reply to it
248Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: start=0xffffffffffffffff
249Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=22
250Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=8
251Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: hash 45572 label 586131867 branch 0
252Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5ce110] after is 1
253Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5ce110)!
254Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: end=0x7f983a5ce110
255Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
256Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: incoming reply
257Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_should_relay_response: T_code=180, new_code=180
258Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: T_state=5, branch=0, save=0, relay=0, cancel_BM=0
259Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 8, id 0 entered
260Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: 0x7f983a5d26a8 totag in rpl is <61c51e14> (8)
261Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: branch with tag <61c51e14> already exists
262Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res:  old size: 552, new size: 490
263Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res: copied size: orig:260, new: 490, rest: 292 msg=#012SIP/2.0 180 Ringing#015#012CSeq: 1 INVITE#015#012Call-ID: c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0#015#012From: "1001" <sip:1001@192.168.56.203>;tag=423a329a#015#012To: <sip:1002@192.168.56.203>;tag=61c51e14#015#012Via: SIP/2.0/UDP 192.168.56.1:5060;branch=z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537#015#012Record-Route: <sip:192.168.56.203;lr;did=dc1.92af5555>#015#012Contact: "1002" <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0
264Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 64, id 0 entered
265Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 2 to state 2, due event 2
266Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: sent buf=0x7f983e394e90: SIP/2.0 1..., shmem=0x7f983a5d1ee0: SIP/2.0 1
267Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 128, id 2 entered
268Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_tmcb_func: Called callback for transaction 0x7f983a5ce110 type 128 reply_code=180 branch=0
269Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
270Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
271Apr 26 05:03:40 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: cleaning up
272Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg: SIP Reply  (status):
273Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  version: <SIP/2.0>
274Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  status:  <200>
275Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  reason:  <OK>
276Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=2
277Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
278Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=61c51e14
279Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
280Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
281Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1002@192.168.56.203]
282Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>]
283Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK402b.b99afe22.0>; state=9
284Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: next_via
285Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537>; state=16
286Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: end of header reached, state=5
287Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: via found, flags=2
288Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: this is the first via
289Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: After parse_msg...
290Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:forward_reply: found module tm, passing reply to it
291Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: start=0xffffffffffffffff
292Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=22
293Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=8
294Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: hash 45572 label 586131867 branch 0
295Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5ce110] after is 1
296Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5ce110)!
297Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=8
298Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_check: end=0x7f983a5ce110
299Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
300Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: incoming reply
301Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_should_relay_response: T_code=180, new_code=200
302Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: T_state=4, branch=0, save=0, relay=0, cancel_BM=0
303Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 8, id 0 entered
304Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: 0x7f983a5d26a8 totag in rpl is <61c51e14> (8)
305Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: branch with tag <61c51e14> already exists
306Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:push_reply_in_dialog: Skipping 1 ,0, 0, 1
307Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=80
308Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
309Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: content_length=949
310Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: found end of header
311Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:print_rr_body: current rr is <sip:192.168.56.203;lr;did=dc1.92af5555>
312Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:print_rr_body: skipping 1 route records
313Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:print_rr_body: out rr []
314Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:print_rr_body: we have 1 records
315Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_update_routing: dialog 0x7f983a5d26a8[1]: rr=<> contact=<sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
316Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res:  old size: 1529, new size: 1467
317Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:build_res_buf_from_sip_res: copied size: orig:255, new: 1467, rest: 1274 msg=#012SIP/2.0 200 OK#015#012CSeq: 1 INVITE#015#012Call-ID: c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0#015#012From: "1001" <sip:1001@192.168.56.203>;tag=423a329a#015#012To: <sip:1002@192.168.56.203>;tag=61c51e14#015#012Via: SIP/2.0/UDP 192.168.56.1:5060;branch=z9hG4bK-383534-3422e40c3a12e84f2dff0f0ac10a6537#015#012Record-Route: <sip:192.168.56.203;lr;did=dc1.92af5555>#015#012Contact: "1002" <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Type: application/sdp#015#012Content-Length: 949#015#012#015#012v=0#015#012o=1002-jitsi.org 0 0 IN IP4 192.168.56.1#015#012s=-#015#012c=IN IP4 192.168.56.1#015#012t=0 0#015#012m=audio 5020 RTP/AVP 96 97 98 9 100 102 0 8 103 3 104 4 101#015#012a=rtpmap:96 opus/48000/2#015#012a=fmtp:96 usedtx=1#015#012a=ptime:20#015#012a=rtpmap:97 SILK/24000#015#012a=rtpmap:98 SILK/16000#015#012a=rtpmap:9 G722/8000#015#012a=rtpmap:100 speex/32000#015#012a=rtpmap:102 speex/16000#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:103 iLBC/8000#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:104 speex/8000#015#012a=rtpmap:4 G723/8000#015#012a=fmtp:4 annexa=no;bitrate=6.3#015#012a=rtpmap:101 telephone-event/8000#015#012a=extmap:1 urn:ietf:params:rtp-hdrext:csrc-audio-level#015#012a=extmap:2 urn:ietf:params:rtp-hdrext:ssrc-audio-level#015#012a=rtcp-xr:voip-metrics#015#012m=video 5022 RTP/AVP 105 99#015#012a=inactive#015#012a=rtpmap:105 H264/90000#015#012a=fmtp:105 profile-level-id=4DE01f;packetization-mode=1#015#012a=imageattr:105 send * recv [x=[1:1920],y=[1:1080]]#015#012a=rtpmap:99 H264/90000#015#012a=fmtp:99 profile-level-id=4DE01f#015#012a=imageattr:99 send * recv [x=[1:1920],y=[1:1080]]
318Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:update_totag_set: new totag
319Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [2]: 0x7f983a5ce190 (273)
320Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 64, id 0 entered
321Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding string param
322Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding string param
323Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding string param
324Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding string param
325Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding string param
326Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding int param
327Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:evi_param_set: adding int param
328Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
329Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 2 to state 3, due event 3
330Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_onreply: dialog 0x7f983a5d26a8 confirmed
331Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0x7f983a5d26f8 for 43468
332Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 3
333Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: sent buf=0x7f983e3953f0: SIP/2.0 2..., shmem=0x7f983a5d4628: SIP/2.0 2
334Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5ce110, callback type 128, id 2 entered
335Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_tmcb_func: Called callback for transaction 0x7f983a5ce110 type 128 reply_code=200 branch=0
336Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 4
337Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_handle_cmd: sending json string: { "method": "SessionSv1.InitiateSession", "id": 657063434, "params": [ { "ProcessStatQueues": true, "ProcessThresholds": true, "AuthorizeResources": true, "GetSuppliers": true, "GetAttributes": true, "GetMaxUsage": true, "Event": { "RequestType": "*prepaid", "OriginID": "c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0", "DialogID": 1431697961, "DialogEntry": 461, "Account": "1001", "SetupTime": "1524733418", "AnswerTime": "1524733421", "Destination": "1002" }, "InitSession": true } ] }
338Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_get_default_conn: conn=0x7f983e394528 state=2 now=1524733421 until=1524733432
339Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:lookup_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 5
340Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:lookup_dlg: dialog id=1431697961 found on entry 461
341Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:init_dlg_term_reason: Setting DLG term reason to [CGRateS Accounting Denied]
342Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:send_leg_bye: sending BYE on dialog 0x7f983a5d26a8 to caller (0)
343Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 6
344Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 7
345Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: CRITICAL:dialog:send_leg_bye: sending BYE for dialog 0x7f983a5d26a8
346Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_uac: next_hop=<sip:1001@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
347Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:mk_proxy: doing DNS lookup...
348Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_uac: sending socket is 192.168.56.203
349Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:dlg2hash: 45572
350Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:print_request_uri: sip:1001@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203
351Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:set_timer: relative timeout is 500000
352Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [4]: 0x7f983a5d4e70 (268900000)
353Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [0]: 0x7f983a5d4ea0 (273)
354Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 6 in entry 0x7f983a570fe8
355Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:send_leg_bye: BYE sent to caller
356Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:send_leg_bye: sending BYE on dialog 0x7f983a5d26a8 to callee (1)
357Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 7
358Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 8
359Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: CRITICAL:dialog:send_leg_bye: sending BYE for dialog 0x7f983a5d26a8
360Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_uac: next_hop=<sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
361Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:mk_proxy: doing DNS lookup...
362Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_uac: sending socket is 192.168.56.203
363Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:dlg2hash: 45569
364Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:print_request_uri: sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203
365Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:set_timer: relative timeout is 500000
366Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [4]: 0x7f983a5d69a0 (268900000)
367Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [0]: 0x7f983a5d69d0 (273)
368Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 7 in entry 0x7f983a570fe8
369Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:send_leg_bye: BYE sent to callee
370Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 6 in entry 0x7f983a570fe8
371Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
372Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
373Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 5 in entry 0x7f983a570fe8
374Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
375Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: cleaning up
376Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg: SIP Request:
377Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  method:  <ACK>
378Apr 26 05:03:41 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
379Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_msg:  version: <SIP/2.0>
380Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=2
381Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <ACK>
382Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-da7f339108604783465d28bdce01da68>; state=16
383Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_via: end of header reached, state=5
384Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: via found, flags=2
385Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: this is the first via
386Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: After parse_msg...
387Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: preparing to run routing scripts...
388Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:sl:sl_filter_ACK: too late to be a local ACK!
389Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=100
390Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=61c51e14
391Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
392Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={"1002"}, ruri={sip:1002@192.168.56.203}
393Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:1002@192.168.56.203]
394Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: to body ["1002" <sip:1002@192.168.56.203>]
395Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:maxfwd:is_maxfwd_present: value = 70
396Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:uri:has_totag: totag found
397Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=78
398Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: start searching: hash=45572, isACK=1
399Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=38
400Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_to_param: tag=423a329a
401Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg: SIP Reply  (status):
402Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: end of header reached, state=29
403Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  version: <SIP/2.0>
404Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
405Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  status:  <200>
406Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f983a5ce110] after is 1
407Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  reason:  <OK>
408Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_lookup_request: e2e proxy ACK found
409Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=2
410Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=200
411Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <BYE>
412Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:rr:is_preloaded: No
413Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=423a329a
414Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
415Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
416Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
417Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={}, ruri={sip:1001@192.168.56.203}
418Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
419Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1001@192.168.56.203]
420Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
421Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: to body [<sip:1001@192.168.56.203>]
422Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
423Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK402b.c99afe22.0>; state=16
424Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
425Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: end of header reached, state=5
426Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
427Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: via found, flags=2
428Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_msg: SIP Reply  (status):
429Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
430Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: this is the first via
431Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_msg:  version: <SIP/2.0>
432Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:check_self: host != me
433Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: After parse_msg...
434Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_msg:  status:  <200>
435Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
436Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:forward_reply: found module tm, passing reply to it
437Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_msg:  reason:  <OK>
438Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
439Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_check: start=0xffffffffffffffff
440Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_headers: flags=2
441Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
442Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=22
443Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
444Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
445Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: hash 45572 label 586131868 branch 0
446Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_to_param: tag=61c51e14
447Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
448Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5d4c50] after is 1
449Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:_parse_to: end of header reached, state=29
450Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
451Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5d4c50)!
452Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:_parse_to: display={}, ruri={sip:1002@192.168.56.203}
453Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.56.203;lr;did=dc1.92af5555' is me
454Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_check: end=0x7f983a5d4c50
455Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:get_hdr_field: <To> [40]; uri=[sip:1002@192.168.56.203]
456Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=200
457Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
458Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:get_hdr_field: to body [<sip:1002@192.168.56.203>]
459Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: content_length=0
460Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
461Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK102b.1688b5a1.0>; state=16
462Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:get_hdr_field: found end of header
463Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:local_reply: branch=0, save=0, winner=0
464Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_via: end of header reached, state=5
465Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:rr:find_next_route: No next Route HF found
466Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:local_reply: local transaction completed
467Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_headers: via found, flags=2
468Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:rr:after_loose: No next URI found!
469Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:run_trans_callbacks: trans=0x7f983a5d4c50, callback type 256, id 0 entered
470Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_headers: this is the first via
471Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=dc1.92af5555>
472Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:bye_reply_cb: receiving a final reply 200 for transaction 0x7f983a5d4c50, dialog 0x7f983a5d26a8
473Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:receive_msg: After parse_msg...
474Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_onroute: route param is 'dc1.92af5555' (len=12)
475Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
476Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:dialog:lookup_dlg: no dialog id=1431697961 found on entry 461
477Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
478Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:dialog:dlg_onroute: unable to find dialog for ACK with route param 'dc1.92af5555'
479Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_newtran: transaction on entrance=(nil)
480Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
481Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
482Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
483Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:forward_reply: found module tm, passing reply to it
484Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_newtran: building branch for end2end ACK - flags=1
485Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding string param
486Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_check: start=0xffffffffffffffff
487Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_relay_to: forwarding ACK
488Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding int param
489Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:parse_headers: flags=22
490Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:mk_proxy: doing DNS lookup...
491Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:evi_param_set: adding int param
492Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_reply_matching: hash 45569 label 442206305 branch 0
493Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:forward_request: sending:#012ACK sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203 SIP/2.0#015#012Call-ID: c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0#015#012CSeq: 1 ACK#015#012Via: SIP/2.0/UDP 192.168.56.203:5060;branch=z9hG4bK402b.b99afe22.2#015#012Via: SIP/2.0/UDP 192.168.56.1:5060;branch=z9hG4bK-383534-da7f339108604783465d28bdce01da68#015#012From: "1001" <sip:1001@192.168.56.203>;tag=423a329a#015#012To: "1002" <sip:1002@192.168.56.203>;tag=61c51e14#015#012Max-Forwards: 69#015#012Contact: "1001" <sip:1001@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>#015#012User-Agent: Jitsi2.10.5550Windows 10#015#012Content-Length: 0#015#012#015#012.
494Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
495Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f983a5d6780] after is 1
496Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:forward_request: orig. len=569, new_len=588, proto=1
497Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 3 to state 5, due event 7
498Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_reply_matching: reply matched (T=0x7f983a5d6780)!
499Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7f983a5ce110] after is 0
500Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:dual_bye_event: removing dialog with h_entry 461 and h_id 1431697961
501Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_check: end=0x7f983a5d6780
502Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:destroy_avp_list: destroying list (nil)
503Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:ref_dlg: ref dlg 0x7f983a5d26a8 with 1 -> 6
504Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_msg: SIP Request:
505Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
506Apr 26 05:03:42 teo /usr/sbin/opensips[7490]: DBG:core:receive_msg: cleaning up
507Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:run_dlg_callbacks: dialog=0x7f983a5d26a8, type=32
508Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_msg:  method:  <BYE>
509Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
510Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:cgrates:cgr_ref_acc_ctx: dialog ref=2 ctx=0x7f983a5d3560
511Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
512Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:local_reply: branch=0, save=0, winner=0
513Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 5 in entry 0x7f983a570fe8
514Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_msg:  version: <SIP/2.0>
515Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:local_reply: local transaction completed
516Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:dual_bye_event: first final reply
517Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=2
518Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:run_trans_callbacks: trans=0x7f983a5d6780, callback type 256, id 0 entered
519Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 2 -> 3 in entry 0x7f983a570fe8
520Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
521Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:dialog:bye_reply_cb: receiving a final reply 200 for transaction 0x7f983a5d6780, dialog 0x7f983a5d26a8
522Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
523Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_to_param: tag=61c51e14
524Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 5 to state 5, due event 7
525Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:insert_timer_unsafe: [2]: 0x7f983a5d4cd0 (273)
526Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:_parse_to: end of header reached, state=29
527Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:dialog:dual_bye_event: second final reply
528Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d4c50] after is 0
529Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:_parse_to: display={"1002"}, ruri={sip:1002@192.168.56.203}
530Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 0 -> 3 in entry 0x7f983a570fe8
531Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
532Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:1002@192.168.56.203]
533Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
534Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: cleaning up
535Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:get_hdr_field: to body ["1002" <sip:1002@192.168.56.203>]
536Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:insert_timer_unsafe: [2]: 0x7f983a5d6800 (273)
537Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-7a30f9be8c82d821ca12c3cc7731cede>; state=16
538Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d6780] after is 0
539Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_via: end of header reached, state=5
540Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:destroy_avp_list: destroying list (nil)
541Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: via found, flags=2
542Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:core:receive_msg: cleaning up
543Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: this is the first via
544Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:receive_msg: After parse_msg...
545Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:receive_msg: preparing to run routing scripts...
546Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:maxfwd:is_maxfwd_present: value = 70
547Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:uri:has_totag: totag found
548Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=200
549Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:rr:is_preloaded: No
550Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
551Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
552Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
553Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
554Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
555Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
556Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
557Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
558Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:check_self: host != me
559Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
560Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
561Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
562Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
563Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
564Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
565Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.56.203;lr;did=dc1.92af5555' is me
566Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=200
567Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:get_hdr_field: content_length=0
568Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:get_hdr_field: found end of header
569Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:rr:find_next_route: No next Route HF found
570Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:rr:after_loose: No next URI found!
571Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=dc1.92af5555>
572Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:dialog:dlg_onroute: route param is 'dc1.92af5555' (len=12)
573Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:dialog:lookup_dlg: no dialog id=1431697961 found on entry 461
574Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param 'dc1.92af5555'
575Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=78
576Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_to_param: tag=423a329a
577Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:_parse_to: end of header reached, state=29
578Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
579Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
580Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=ffffffffffffffff
581Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:parse_headers: flags=78
582Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:t_lookup_request: start searching: hash=45569, isACK=0
583Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:matching_3261: RFC3261 transaction matching failed
584Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:t_lookup_request: no transaction found
585Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:run_reqin_callbacks: trans=0x7f983a5d87c0, callback type 1, id 1 entered
586Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:run_reqin_callbacks: trans=0x7f983a5d87c0, callback type 1, id 0 entered
587Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:mk_proxy: doing DNS lookup...
588Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:set_timer: relative timeout is 500000
589Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:insert_timer_unsafe: [4]: 0x7f983a5d89e0 (269000000)
590Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:insert_timer_unsafe: [0]: 0x7f983a5d8a10 (273)
591Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:t_relay_to: new transaction fwd'ed
592Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d87c0] after is 0
593Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:destroy_avp_list: destroying list (nil)
594Apr 26 05:03:42 teo /usr/sbin/opensips[7487]: DBG:core:receive_msg: cleaning up
595Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f983a5d4e70 next=0x7f983a5d69a0, timeout=268900000
596Apr 26 05:03:42 teo /usr/sbin/opensips[7489]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f983a5d69a0 next=(nil), timeout=268900000
597Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg: SIP Request:
598Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  method:  <BYE>
599Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
600Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  version: <SIP/2.0>
601Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=2
602Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
603Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=61c51e14
604Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
605Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1002"}, ruri={sip:1002@192.168.56.203}
606Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:1002@192.168.56.203]
607Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: to body ["1002" <sip:1002@192.168.56.203>]
608Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-7a30f9be8c82d821ca12c3cc7731cede>; state=16
609Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: end of header reached, state=5
610Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: via found, flags=2
611Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: this is the first via
612Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: After parse_msg...
613Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: preparing to run routing scripts...
614Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:maxfwd:is_maxfwd_present: value = 70
615Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:uri:has_totag: totag found
616Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
617Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:rr:is_preloaded: No
618Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
619Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
620Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
621Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
622Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
623Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
624Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
625Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
626Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:check_self: host != me
627Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
628Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
629Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
630Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
631Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
632Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
633Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.56.203;lr;did=dc1.92af5555' is me
634Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
635Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: content_length=0
636Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: found end of header
637Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:rr:find_next_route: No next Route HF found
638Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: No next URI found!
639Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=dc1.92af5555>
640Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: route param is 'dc1.92af5555' (len=12)
641Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:lookup_dlg: no dialog id=1431697961 found on entry 461
642Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param 'dc1.92af5555'
643Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
644Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=423a329a
645Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
646Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
647Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
648Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=ffffffffffffffff
649Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
650Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: start searching: hash=45569, isACK=0
651Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=-383534-7a30f9be8c82d821ca12c3cc7731cede
652Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f983a5d87c0] after is 1
653Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: transaction found (T=0x7f983a5d87c0)
654Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_retransmit_reply: nothing to retransmit
655Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d87c0] after is 0
656Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
657Apr 26 05:03:42 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: cleaning up
658Apr 26 05:03:42 teo /usr/sbin/opensips[7483]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f983a5d89e0 next=(nil), timeout=269000000
659Apr 26 05:03:42 teo /usr/sbin/opensips[7483]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f983a5d87c0, BYE sip:1 ... )
660Apr 26 05:03:42 teo /usr/sbin/opensips[7483]: DBG:tm:set_timer: relative timeout is 1000000
661Apr 26 05:03:42 teo /usr/sbin/opensips[7483]: DBG:tm:insert_timer_unsafe: [5]: 0x7f983a5d89e0 (270000000)
662Apr 26 05:03:42 teo /usr/sbin/opensips[7483]: DBG:tm:retransmission_handler: retransmission_handler : done
663Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg: SIP Request:
664Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  method:  <BYE>
665Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
666Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  version: <SIP/2.0>
667Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=2
668Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
669Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=61c51e14
670Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
671Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1002"}, ruri={sip:1002@192.168.56.203}
672Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:1002@192.168.56.203]
673Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: to body ["1002" <sip:1002@192.168.56.203>]
674Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-7a30f9be8c82d821ca12c3cc7731cede>; state=16
675Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: end of header reached, state=5
676Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: via found, flags=2
677Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: this is the first via
678Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: After parse_msg...
679Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: preparing to run routing scripts...
680Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:maxfwd:is_maxfwd_present: value = 70
681Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:uri:has_totag: totag found
682Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
683Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:rr:is_preloaded: No
684Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
685Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
686Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
687Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
688Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
689Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
690Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
691Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
692Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:check_self: host != me
693Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
694Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
695Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
696Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
697Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
698Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
699Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.56.203;lr;did=dc1.92af5555' is me
700Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
701Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: content_length=0
702Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: found end of header
703Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:rr:find_next_route: No next Route HF found
704Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: No next URI found!
705Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=dc1.92af5555>
706Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: route param is 'dc1.92af5555' (len=12)
707Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:dialog:lookup_dlg: no dialog id=1431697961 found on entry 461
708Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param 'dc1.92af5555'
709Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
710Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=423a329a
711Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
712Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
713Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
714Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=ffffffffffffffff
715Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
716Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: start searching: hash=45569, isACK=0
717Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=-383534-7a30f9be8c82d821ca12c3cc7731cede
718Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f983a5d87c0] after is 1
719Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: transaction found (T=0x7f983a5d87c0)
720Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_retransmit_reply: nothing to retransmit
721Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d87c0] after is 0
722Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
723Apr 26 05:03:43 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: cleaning up
724Apr 26 05:03:43 teo /usr/sbin/opensips[7495]: DBG:tm:utimer_routine: timer routine:5,tl=0x7f983a5d89e0 next=(nil), timeout=270000000
725Apr 26 05:03:43 teo /usr/sbin/opensips[7495]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f983a5d87c0, BYE sip:1 ... )
726Apr 26 05:03:43 teo /usr/sbin/opensips[7495]: DBG:tm:set_timer: relative timeout is 2000000
727Apr 26 05:03:43 teo /usr/sbin/opensips[7495]: DBG:tm:insert_timer_unsafe: [6]: 0x7f983a5d89e0 (272800000)
728Apr 26 05:03:43 teo /usr/sbin/opensips[7495]: DBG:tm:retransmission_handler: retransmission_handler : done
729Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg: SIP Request:
730Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  method:  <BYE>
731Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  uri:     <sip:1002@192.168.56.1:5060;transport=udp;registering_acc=192_168_56_203>
732Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_msg:  version: <SIP/2.0>
733Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=2
734Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
735Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=61c51e14
736Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
737Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1002"}, ruri={sip:1002@192.168.56.203}
738Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:1002@192.168.56.203]
739Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: to body ["1002" <sip:1002@192.168.56.203>]
740Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-383534-7a30f9be8c82d821ca12c3cc7731cede>; state=16
741Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_via: end of header reached, state=5
742Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: via found, flags=2
743Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: this is the first via
744Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: After parse_msg...
745Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: preparing to run routing scripts...
746Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:maxfwd:is_maxfwd_present: value = 70
747Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:uri:has_totag: totag found
748Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
749Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:rr:is_preloaded: No
750Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
751Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
752Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==9 &&  [192.168.56.1] == [127.0.0.1]
753Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
754Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
755Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
756Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 12==14 &&  [192.168.56.1] == [192.168.56.203]
757Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
758Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:check_self: host != me
759Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
760Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
761Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [192.168.56.203] == [127.0.0.1]
762Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
763Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if host==us: 14==14 &&  [192.168.56.203] == [192.168.56.203]
764Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
765Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.56.203;lr;did=dc1.92af5555' is me
766Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=200
767Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: content_length=0
768Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:get_hdr_field: found end of header
769Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:rr:find_next_route: No next Route HF found
770Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:rr:after_loose: No next URI found!
771Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=dc1.92af5555>
772Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: route param is 'dc1.92af5555' (len=12)
773Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:dialog:lookup_dlg: no dialog id=1431697961 found on entry 461
774Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param 'dc1.92af5555'
775Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
776Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_to_param: tag=423a329a
777Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: end of header reached, state=29
778Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:_parse_to: display={"1001"}, ruri={sip:1001@192.168.56.203}
779Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
780Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=ffffffffffffffff
781Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:parse_headers: flags=78
782Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: start searching: hash=45569, isACK=0
783Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=-383534-7a30f9be8c82d821ca12c3cc7731cede
784Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7f983a5d87c0] after is 1
785Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_lookup_request: transaction found (T=0x7f983a5d87c0)
786Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_retransmit_reply: nothing to retransmit
787Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7f983a5d87c0] after is 0
788Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:destroy_avp_list: destroying list (nil)
789Apr 26 05:03:45 teo /usr/sbin/opensips[7488]: DBG:core:receive_msg: cleaning up
790Apr 26 05:03:45 teo /usr/sbin/opensips[7487]: DBG:tm:utimer_routine: timer routine:6,tl=0x7f983a5d89e0 next=(nil), timeout=272800000
791Apr 26 05:03:45 teo /usr/sbin/opensips[7487]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f983a5d87c0, BYE sip:1 ... )
792Apr 26 05:03:45 teo /usr/sbin/opensips[7487]: DBG:tm:set_timer: relative timeout is 4000000
793Apr 26 05:03:45 teo /usr/sbin/opensips[7487]: DBG:tm:insert_timer_unsafe: [7]: 0x7f983a5d89e0 (276800000)
794Apr 26 05:03:45 teo /usr/sbin/opensips[7487]: DBG:tm:retransmission_handler: retransmission_handler : done
795Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:0,tl=0x7f983a5d4ea0 next=0x7f983a5d69d0, timeout=273
796Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:0,tl=0x7f983a5d69d0 next=0x7f983a5d8a10, timeout=273
797Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:0,tl=0x7f983a5d8a10 next=(nil), timeout=273
798Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f983a5d87c0)
799Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:t_should_relay_response: T_code=0, new_code=408
800Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)
801Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=0
802Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:t_should_relay_response: trying DNS-based failover
803Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: T_state=4, branch=0, save=0, relay=0, cancel_BM=0
804Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:core:parse_headers: flags=ffffffffffffffff
805Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:core:_shm_resize: resize(0) called
806Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:insert_timer_unsafe: [2]: 0x7f983a5d8840 (278)
807Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:relay_reply: sent buf=0x7f983e3977f8: SIP/2.0 4..., shmem=0x7f983a5dbcd0: SIP/2.0 4
808Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:run_trans_callbacks: trans=0x7f983a5d87c0, callback type 128, id 0 entered
809Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:acc:acc_log_request: no legs
810Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: ACC: transaction answered: timestamp=1524733426;method=BYE;from_tag=423a329a;to_tag=61c51e14;call_id=c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0;code=408;reason=Request Timeout
811Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:final_response_handler: done
812Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:2,tl=0x7f983a5ce190 next=0x7f983a5d4cd0, timeout=273
813Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: removing 0x7f983a5ce110 from table
814Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:delete_cell: delete transaction 0x7f983a5ce110
815Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_ref_acc_ctx: tm ref=1 ctx=0x7f983a5d3560
816Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:next_state_dlg: dialog 0x7f983a5d26a8 changed from state 5 to state 5, due event 1
817Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 2 in entry 0x7f983a570fe8
818Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_free_ctx: release ctx=0x7f983a5cda98
819Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_ref_acc_ctx: general ctx ref=0 ctx=0x7f983a5d3560
820Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:cgrates:cgr_free_acc_ctx: release acc ctx=0x7f983a5d3560
821Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: done
822Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:2,tl=0x7f983a5d4cd0 next=0x7f983a5d6800, timeout=273
823Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: removing 0x7f983a5d4c50 from table
824Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:delete_cell: delete transaction 0x7f983a5d4c50
825Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 1 in entry 0x7f983a570fe8
826Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: done
827Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:timer_routine: timer routine:2,tl=0x7f983a5d6800 next=(nil), timeout=273
828Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: removing 0x7f983a5d6780 from table
829Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:delete_cell: delete transaction 0x7f983a5d6780
830Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: unref dlg 0x7f983a5d26a8 with 1 -> 0 in entry 0x7f983a570fe8
831Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:unref_dlg: ref <=0 for dialog 0x7f983a5d26a8, destroying it
832Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:destroy_dlg: destroying dialog 0x7f983a5d26a8
833Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x7f983a5d26a8 [461:1431697961] with clid 'c6dff1f72d88aef872dac0876d870c90@0:0:0:0:0:0:0:0' and tags '423a329a' '61c51e14'
834Apr 26 05:03:46 teo /usr/sbin/opensips[7490]: DBG:tm:wait_handler: done