[SR-Users] Missing ACC record in case of canceled call forking

Daniel-Constantin Mierla miconda at gmail.com
Mon Sep 10 19:48:11 CEST 2018


Hello,

pushed another commit:

  -
https://github.com/kamailio/kamailio/commit/35dec4c20d78f49ba242229c877894d70c94705c

Give it a try and let's see the results.

Cheers,
Daniel


On 10.09.18 16:08, Marco Capetta wrote:
> Hello,
>
> the issue seems still there.
> Please find attached the new log with debug 3.
>
> Thanks
> Marco
>
>
> On 09/10/2018 03:14 PM, Daniel-Constantin Mierla wrote:
>>
>> Hello,
>>
>> can you try with:
>>
>> https://github.com/kamailio/kamailio/commit/5b223a2e8a92f351b8eab756f5256fda7645ff21
>>
>> If still a problem, send again all the logs with debug=3.
>>
>> Cheers,
>> Daniel
>>
>>
>> On 10.09.18 13:55, Marco Capetta wrote:
>>> Hi Daniel,
>>>
>>> sorry for the misunderstanding.
>>> Attached to the mail you can find the full log of the affected call
>>> with debug level 3 as requested.
>>>
>>> Thank you again
>>>
>>> Cheers,
>>> Marco
>>>
>>>
>>> On 09/10/2018 12:29 PM, Daniel-Constantin Mierla wrote:
>>>>
>>>> Hello,
>>>>
>>>> I need **all the logs**, not only those from acc module and script,
>>>> but all the modules and core.
>>>>
>>>> Add also:
>>>>
>>>> log_prefix="{$mt $hdr(CSeq) $ci} "
>>>>
>>>> to be able to match log message with the request time.
>>>>
>>>> And again, send the logs only for the case that fails.
>>>>
>>>> Cheers,
>>>> Daniel
>>>>
>>>> On 10.09.18 10:57, Marco Capetta wrote:
>>>>> Hi Daniel,
>>>>>
>>>>> I applied your patch to our kamailio v5.1.4 because this is the
>>>>> current version we are using.
>>>>>
>>>>>
>>>>> This is the log + debug of the call when the two INVITEs are
>>>>> leaving kamailio.
>>>>> This part is common for both the call cases:
>>>>>
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: Request leaving
>>>>> server, M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:5080' -
>>>>> R=sip:43993003 at 10.50.16.134:5063 ID=1125655181 at 10.50.3.130
>>>>> UA='YATE/5.4.0'
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: Request leaving
>>>>> server, M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:5080' -
>>>>> R=sip:43993003 at 10.50.16.134:5063 ID=1125655181 at 10.50.3.130
>>>>> UA='YATE/5.4.0'
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 100
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 100 flags: 0x802a
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=100 - Trying M=INVITE IP=10.50.3.126:35901 (127.0.0.1:5080)
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 100
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 100 flags: 0x802a
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=100 - Trying M=INVITE IP=10.50.3.126:35901 (127.0.0.1:5080)
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 180
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 180 flags: 0x802a
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=180 - Ringing M=INVITE IP=10.50.3.126:35901 (127.0.0.1:5080)
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>'      DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=180 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 512, reply code 180
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 180 flags: 0x802a
>>>>> Sep 10 10:33:21 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 180
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 180 flags: 0x802a
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=180 - Ringing M=INVITE IP=10.50.3.126:35901 (127.0.0.1:5080)
>>>>> ID=1125655181 at 10.50.3.130 UA='Yealink SIP-T32G 32.70.1.33'
>>>>> DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=180 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1125655181 at 10.50.3.130 UA='Yealink SIP-T32G 32.70.1.33'
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 512, reply code 180
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 180 flags: 0x802a
>>>>> Sep 10 10:33:22 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:443]:
>>>>> should_acc_reply(): early media acc is off
>>>>>
>>>>>
>>>>>
>>>>> In CASE 1, this is the log + debug printed when the call is
>>>>> canceled from the caller:
>>>>>
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=CANCEL R=sip:43993003 at 10.50.3.130
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1125655181 at 10.50.3.130
>>>>> UA='<null>' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=100 Trying fs='127.0.0.1:5062' du='127.0.0.1:5060' -
>>>>> R=sip:43993003 at 10.50.3.130 ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12c3318) event type
>>>>> 512, reply code 200
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 200 flags: 0x0
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:436]:
>>>>> should_acc_reply(): acc is off
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 200
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 200 flags: 0x802a
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:447]:
>>>>> should_acc_reply(): acc is on
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 487
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 487 flags: 0x802a
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:431]:
>>>>> should_acc_reply(): failed acc is on
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=487 - Request terminated M=INVITE IP=10.50.3.126:35901
>>>>> (127.0.0.1:5080) ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=487 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 200
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 200 flags: 0x802a
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:447]:
>>>>> should_acc_reply(): acc is on
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 2, reply code 487
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 487 flags: 0x802a
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:431]:
>>>>> should_acc_reply(): failed acc is on
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=487 - Request terminated M=INVITE IP=10.50.3.126:35901
>>>>> (127.0.0.1:5080) ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=487 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1125655181 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 128, reply code 487
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:477]:
>>>>> on_missed(): preparing to report the record
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Failure route
>>>>> for local call, code='487' - R=sip:43993003 at 10.50.16.134:5063
>>>>> ID=1125655181 at 10.50.3.130 UA='YATE/5.4.0'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Final reply -
>>>>> R=sip:43993003 at 10.50.16.134:5063 ID=1125655181 at 10.50.3.130
>>>>> UA='YATE/5.4.0'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12b4220) event type
>>>>> 512, reply code 487
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 487 flags: 0x802a
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:431]:
>>>>> should_acc_reply(): failed acc is on
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_extra.h:63]:
>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8,
>>>>> index i 0
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_extra.h:63]:
>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8,
>>>>> index i 1
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_extra.h:63]:
>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8,
>>>>> index i 2
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_extra.h:63]:
>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8,
>>>>> index i 3
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: DEBUG: acc [acc_extra.h:63]:
>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8,
>>>>> index i 4
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=BYE
>>>>> R=sip:127.0.0.1:5062;lr=on;ftag=1714653723;did=2cc.ee71;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=bUViZ2VDb2dwTTNFYU5lTDRmbVVtRWJn
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1125655181 at 10.50.3.130
>>>>> UA='YATE/5.4.0' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=100 Trying fs='127.0.0.1:5062' du='127.0.0.1:5060' -
>>>>> R=sip:127.0.0.1:5062;lr=on;ftag=1714653723;did=2cc.ee71;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=bUViZ2VDb2dwTTNFYU5lTDRmbVVtRWJn
>>>>> ID=1125655181 at 10.50.3.130 UA='YATE/5.4.0'
>>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=ACK R=sip:43993003 at 10.50.3.130
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1125655181 at 10.50.3.130
>>>>> UA='<null>' DESTIP=127.0.0.1:5062
>>>>>
>>>>>
>>>>>
>>>>> In CASE 2, this is the log + debug printed when the call is
>>>>> rejected from one of the callee and then canceled from the caller:
>>>>>
>>>>> Sep 10 10:35:35 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12bbec0) event type
>>>>> 2, reply code 486
>>>>> Sep 10 10:35:35 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 486 flags: 0x802a
>>>>> Sep 10 10:35:35 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:431]:
>>>>> should_acc_reply(): failed acc is on
>>>>> Sep 10 10:35:35 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=486 - Busy Here M=INVITE IP=10.50.3.126:35901 (127.0.0.1:5080)
>>>>> ID=1929423861 at 10.50.3.130 UA='Yealink SIP-T32G 32.70.1.33'
>>>>> DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:35:35 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=486 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1929423861 at 10.50.3.130 UA='Yealink SIP-T32G 32.70.1.33'
>>>>>
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=CANCEL R=sip:43993003 at 10.50.3.130
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1929423861 at 10.50.3.130
>>>>> UA='<null>' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=100 Trying fs='127.0.0.1:5062' du='127.0.0.1:5060' -
>>>>> R=sip:43993003 at 10.50.3.130 ID=1929423861 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12c6b30) event type
>>>>> 512, reply code 200
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 200 flags: 0x0
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:436]:
>>>>> should_acc_reply(): acc is off
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=BYE
>>>>> R=sip:127.0.0.1:5062;lr=on;ftag=1174240048;did=7bd.7c3;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=bUViZ2VDb2dwTTNFYU5lTDRmbVVtRWJn
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1929423861 at 10.50.3.130
>>>>> UA='YATE/5.4.0' DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=100 Trying fs='127.0.0.1:5062' du='127.0.0.1:5060' -
>>>>> R=sip:127.0.0.1:5062;lr=on;ftag=1174240048;did=7bd.7c3;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=bUViZ2VDb2dwTTNFYU5lTDRmbVVtRWJn
>>>>> ID=1929423861 at 10.50.3.130 UA='YATE/5.4.0'
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12bbec0) event type
>>>>> 2, reply code 200
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 200 flags: 0x802a
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:447]:
>>>>> should_acc_reply(): acc is on
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12bbec0) event type
>>>>> 2, reply code 487
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:414]:
>>>>> should_acc_reply(): probing acc state - code: 487 flags: 0x802a
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:431]:
>>>>> should_acc_reply(): failed acc is on
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: NAT-Reply -
>>>>> S=487 - Request terminated M=INVITE IP=10.50.3.126:35901
>>>>> (127.0.0.1:5080) ID=1929423861 at 10.50.3.130 UA='<null>'
>>>>> DESTIP=127.0.0.1:5062
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Sending reply
>>>>> S=487 M=INVITE fs='127.0.0.1:5062' du='127.0.0.1:<null>' -
>>>>> ID=1929423861 at 10.50.3.130 UA='<null>'
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:684]:
>>>>> tmcb_func(): acc callback called for t(0x7f7ac12bbec0) event type
>>>>> 128, reply code 486
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: DEBUG: acc [acc_logic.c:477]:
>>>>> on_missed(): preparing to report the record
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Failure route
>>>>> for local call, code='486' - R=sip:43993003 at 10.50.16.134:5063
>>>>> ID=1929423861 at 10.50.3.130 UA='YATE/5.4.0'
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Final reply -
>>>>> R=sip:43993003 at 10.50.16.134:5063 ID=1929423861 at 10.50.3.130
>>>>> UA='YATE/5.4.0'
>>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: New request on
>>>>> proxy - M=ACK R=sip:43993003 at 10.50.3.130
>>>>> F=sip:43993004 at 10.50.3.130 T=sip:43993003 at 10.50.3.130
>>>>> IP=127.0.0.1:5060 (127.0.0.1:5060) ID=1929423861 at 10.50.3.130
>>>>> UA='<null>' DESTIP=127.0.0.1:5062
>>>>>
>>>>>
>>>>> Thank you
>>>>> Marco
>>>>>
>>>>>
>>>>>
>>>>> On 09/10/2018 09:21 AM, Daniel-Constantin Mierla wrote:
>>>>>>
>>>>>> Hello,
>>>>>>
>>>>>> I pushed a patch to print more debug messages when testing if
>>>>>> accounting should be done or not:
>>>>>>
>>>>>>   -
>>>>>> https://github.com/kamailio/kamailio/commit/f21554c6befaddbc82016d5d498e11ab3720c404
>>>>>>
>>>>>> Can you test with it and send me all debug messages for the
>>>>>> respective transaction in the case that doesn't work?
>>>>>>
>>>>>> Cheers,
>>>>>> Daniel
>>>>>>
>>>>>>
>>>>>> On 04.09.18 14:03, Marco Capetta wrote:
>>>>>>> Hello,
>>>>>>>
>>>>>>> Yes Flag 3 is set at the very beginning when we start handling
>>>>>>> the received INVITE message.
>>>>>>> I checked and it is still active in both the branches of the
>>>>>>> outgoing INVITEs.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> In the 1st case the following ACC is generated:
>>>>>>>         id: 311
>>>>>>>     method: INVITE
>>>>>>>   from_tag:
>>>>>>>     to_tag:
>>>>>>>     callid: 121700311 at X.X.X.X
>>>>>>>   sip_code: 487
>>>>>>> sip_reason: Request terminated
>>>>>>>       time: 2018-09-04 11:55:24
>>>>>>> time_hires: 1536054924.342
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> I missed to say in my previous email that in kamailio ACC
>>>>>>> configuration we have also:
>>>>>>>   modparam("acc", "acc_prepare_always", 1)
>>>>>>>
>>>>>>>
>>>>>>> Thanks
>>>>>>> Marco
>>>>>>>  
>>>>>>>
>>>>>>>
>>>>>>> On 09/04/2018 11:39 AM, Daniel-Constantin Mierla wrote:
>>>>>>>> Hello,
>>>>>>>>
>>>>>>>> is flag 3 set for the INVITE transaction?
>>>>>>>>
>>>>>>>> In the 1st case, is the CANCEL accounted or the INVITE transaction or both?
>>>>>>>>
>>>>>>>> Cheers,
>>>>>>>> Daniel
>>>>>>>>
>>>>>>>>
>>>>>>>> On 04.09.18 11:18, Marco Capetta wrote:
>>>>>>>>> HiAll,
>>>>>>>>>
>>>>>>>>> As additional step I tested the scenario with kamailio v5.1.5 but the
>>>>>>>>> problem seems still there.
>>>>>>>>>
>>>>>>>>> Best regards.
>>>>>>>>> Marco
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On 08/28/2018 03:10 PM, Marco Capetta wrote:
>>>>>>>>>> Hi All,
>>>>>>>>>>
>>>>>>>>>> I'm facing a strange problem of missing ACC record in case of
>>>>>>>>>> parallel call forking.
>>>>>>>>>>
>>>>>>>>>> The scenario is the following:
>>>>>>>>>>  - A subscriber with 1 device registered
>>>>>>>>>>  - B subscriber with 2 device registered (B1 and B2)
>>>>>>>>>>
>>>>>>>>>> CASE 1:
>>>>>>>>>>  - A calls B
>>>>>>>>>>  - B1 and B2 start ringing
>>>>>>>>>>  - A hangups the call before B1 or B2 answers
>>>>>>>>>> Kamailio generates an ACC record.
>>>>>>>>>>
>>>>>>>>>> CASE 2:
>>>>>>>>>>  - A calls B
>>>>>>>>>>  - B1 and B2 start ringing
>>>>>>>>>>  - B1 rejects the call sending back a 486
>>>>>>>>>>  - B2 is still ringing
>>>>>>>>>>  - A hangups the call before B2 answers
>>>>>>>>>> Kamailio DOESN'T generate an ACC record.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> We have Kamailio v5.1.4 with TM module enabled.
>>>>>>>>>>
>>>>>>>>>> ACC configuration is the following:
>>>>>>>>>>   modparam("acc", "early_media", 0)
>>>>>>>>>>   modparam("acc", "report_ack", 0)
>>>>>>>>>>   modparam("acc", "report_cancels", 1)
>>>>>>>>>>   modparam("acc", "detect_direction", 1)
>>>>>>>>>>   modparam("acc", "db_flag", 1)
>>>>>>>>>>   modparam("acc", "db_missed_flag", 2)
>>>>>>>>>>   modparam("acc", "failed_transaction_flag", 3)
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> I increased debug level of TM and ACC modules and I added some debug
>>>>>>>>>> lines as well.
>>>>>>>>>> The difference between the two calls is that, after the CANCEL sent
>>>>>>>>>> by A is processed by Kamailio, in CASE 1 I have the following lines:
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: tm [t_hooks.c:258]:
>>>>>>>>>> run_trans_callbacks_internal(): DBG: trans=0x7f5a88049198, callback
>>>>>>>>>> type 512, id 0 entered
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_logic.c:670]:
>>>>>>>>>> tmcb_func(): acc callback called for t(0x7f5a88049198) event type
>>>>>>>>>> 512, reply code 487
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_extra.h:63]:
>>>>>>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8, index i 0
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_extra.h:63]:
>>>>>>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8, index i 1
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_extra.h:63]:
>>>>>>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8, index i 2
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_extra.h:63]:
>>>>>>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8, index i 3
>>>>>>>>>>   Aug 28 14:21:11 spce proxy[13188]: DEBUG: acc [acc_extra.h:63]:
>>>>>>>>>> free_strar_mem(): Freeing memory, type is 2, message_index 8, index i 4
>>>>>>>>>>
>>>>>>>>>> Those debug lines are not printed for CASE 2.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Is there any configuration I'm missing or is it a bug?
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Thank you very much for your support.
>>>>>>>>>> Marco
>>>>>>>>>>
>>>>>>>>> _______________________________________________
>>>>>>>>> Kamailio (SER) - Users Mailing List
>>>>>>>>> sr-users at lists.kamailio.org
>>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>
>>>>>>> -- 
>>>>>>> *Marco Capetta *
>>>>>>> Operations Engineer
>>>>>>>
>>>>>>> Sipwise GmbH <http://www.sipwise.com> , Campus 21/Europaring F15
>>>>>>> AT-2345 Brunn am Gebirge
>>>>>>>
>>>>>>> Phone:  +43(0)1 301 2044 <tel:+4313012044>
>>>>>>> Email:  mcapetta at sipwise.com <mailto:mcapetta at sipwise.com>
>>>>>>> Website:  www.sipwise.com <http://www.sipwise.com>
>>>>>>>
>>>>>>> Particulars according Austrian Companies Code paragraph 14
>>>>>>> "Sipwise GmbH" - Europaring F15 - 2345 Brunn am Gebirge
>>>>>>> FN:305595f, Commercial Court Vienna, ATU64002206
>>>>>>>
>>>>>>
>>>>>> -- 
>>>>>> Daniel-Constantin Mierla -- www.asipto.com
>>>>>> www.twitter.com/miconda -- www.linkedin.com/in/miconda
>>>>>> Kamailio World Conference -- www.kamailioworld.com
>>>>>> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
>>>>>
>>>>> -- 
>>>>> *Marco Capetta *
>>>>> Operations Engineer
>>>>>
>>>>> Sipwise GmbH <http://www.sipwise.com> , Campus 21/Europaring F15
>>>>> AT-2345 Brunn am Gebirge
>>>>>
>>>>> Phone:  +43(0)1 301 2044 <tel:+4313012044>
>>>>> Email:  mcapetta at sipwise.com <mailto:mcapetta at sipwise.com>
>>>>> Website:  www.sipwise.com <http://www.sipwise.com>
>>>>>
>>>>> Particulars according Austrian Companies Code paragraph 14
>>>>> "Sipwise GmbH" - Europaring F15 - 2345 Brunn am Gebirge
>>>>> FN:305595f, Commercial Court Vienna, ATU64002206
>>>>>
>>>>
>>>> -- 
>>>> Daniel-Constantin Mierla -- www.asipto.com
>>>> www.twitter.com/miconda -- www.linkedin.com/in/miconda
>>>> Kamailio World Conference -- www.kamailioworld.com
>>>> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
>>>
>>> -- 
>>> *Marco Capetta *
>>> Operations Engineer
>>>
>>> Sipwise GmbH <http://www.sipwise.com> , Campus 21/Europaring F15
>>> AT-2345 Brunn am Gebirge
>>>
>>> Phone:  +43(0)1 301 2044 <tel:+4313012044>
>>> Email:  mcapetta at sipwise.com <mailto:mcapetta at sipwise.com>
>>> Website:  www.sipwise.com <http://www.sipwise.com>
>>>
>>> Particulars according Austrian Companies Code paragraph 14
>>> "Sipwise GmbH" - Europaring F15 - 2345 Brunn am Gebirge
>>> FN:305595f, Commercial Court Vienna, ATU64002206
>>>
>>
>> -- 
>> Daniel-Constantin Mierla -- www.asipto.com
>> www.twitter.com/miconda -- www.linkedin.com/in/miconda
>> Kamailio World Conference -- www.kamailioworld.com
>> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com
>
> -- 
> *Marco Capetta *
> Operations Engineer
>
> Sipwise GmbH <http://www.sipwise.com> , Campus 21/Europaring F15
> AT-2345 Brunn am Gebirge
>
> Phone:  +43(0)1 301 2044 <tel:+4313012044>
> Email:  mcapetta at sipwise.com <mailto:mcapetta at sipwise.com>
> Website:  www.sipwise.com <http://www.sipwise.com>
>
> Particulars according Austrian Companies Code paragraph 14
> "Sipwise GmbH" - Europaring F15 - 2345 Brunn am Gebirge
> FN:305595f, Commercial Court Vienna, ATU64002206
>

-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference -- www.kamailioworld.com
Kamailio Advanced Training, Nov 12-14, 2018, in Berlin -- www.asipto.com

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20180910/f62b36df/attachment.html>


More information about the sr-users mailing list