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/5b223a2e8a92f351b8eab756f5256fd…
>
> 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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5080
>>>> <http://127.0.0.1:5080>' -
R=sip:43993003@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5080
>>>> <http://127.0.0.1:5080>' -
R=sip:43993003@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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
>>>> <http://10.50.3.126:35901> (127.0.0.1:5080
>>>> <http://127.0.0.1:5080>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://10.50.3.126:35901> (127.0.0.1:5080
>>>> <http://127.0.0.1:5080>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://10.50.3.126:35901> (127.0.0.1:5080
>>>> <http://127.0.0.1:5080>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130>
UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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
>>>> <http://10.50.3.126:35901> (127.0.0.1:5080
>>>> <http://127.0.0.1:5080>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='Yealink SIP-T32G
>>>> 32.70.1.33' DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> F=sip:43993004@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5060
>>>> <http://127.0.0.1:5060>' - R=sip:43993003@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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 <http://10.50.3.126:35901>
>>>> (127.0.0.1:5080 <http://127.0.0.1:5080>)
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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 <http://10.50.3.126:35901>
>>>> (127.0.0.1:5080 <http://127.0.0.1:5080>)
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='YATE/5.4.0'
>>>> Sep 10 10:33:33 sp1 proxy[7627]: NOTICE: <script>: Final
>>>> reply - R=sip:43993003@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@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@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='YATE/5.4.0'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5060
>>>> <http://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(a)10.50.3.130
>>>> <mailto:ID=1125655181@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@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> F=sip:43993004@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1125655181(a)10.50.3.130
>>>> <mailto:ID=1125655181@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://10.50.3.126:35901> (127.0.0.1:5080
>>>> <http://127.0.0.1:5080>) ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='Yealink SIP-T32G
>>>> 32.70.1.33' DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@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@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> F=sip:43993004@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5060
>>>> <http://127.0.0.1:5060>' - R=sip:43993003@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@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@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='YATE/5.4.0'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1:5060
>>>> <http://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(a)10.50.3.130
>>>> <mailto:ID=1929423861@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 <http://10.50.3.126:35901>
>>>> (127.0.0.1:5080 <http://127.0.0.1:5080>)
>>>> ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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
>>>> <http://127.0.0.1:5062>' du='127.0.0.1
>>>> <http://127.0.0.1>:<null>' -
ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@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@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='YATE/5.4.0'
>>>> Sep 10 10:35:43 sp1 proxy[7627]: NOTICE: <script>: Final
>>>> reply - R=sip:43993003@10.50.16.134:5063
>>>> <mailto:R=sip:43993003@10.50.16.134:5063>
>>>> ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@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@10.50.3.130
>>>> <mailto:R=sip:43993003@10.50.3.130>
>>>> F=sip:43993004@10.50.3.130
>>>> <mailto:F=sip:43993004@10.50.3.130>
>>>> T=sip:43993003@10.50.3.130
>>>> <mailto:T=sip:43993003@10.50.3.130> IP=127.0.0.1:5060
>>>> <http://127.0.0.1:5060> (127.0.0.1:5060
>>>> <http://127.0.0.1:5060>) ID=1929423861(a)10.50.3.130
>>>> <mailto:ID=1929423861@10.50.3.130> UA='<null>'
>>>> DESTIP=127.0.0.1:5062 <http://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/f21554c6befaddbc82016d5d498e11a…
>>>>>
>>>>> 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(a)X.X.X.X
<mailto:121700311@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(a)lists.kamailio.org
>>>>>>>> <mailto:sr-users@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(a)sipwise.com
<mailto:mcapetta@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
<http://www.asipto.com>
>>>>>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda
>>>>> <http://www.linkedin.com/in/miconda>
>>>>> Kamailio World Conference --
www.kamailioworld.com
<http://www.kamailioworld.com>
>>>>> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin --
www.asipto.com <http://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(a)sipwise.com <mailto:mcapetta@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 <http://www.asipto.com>
>>>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
>>> Kamailio World Conference --
www.kamailioworld.com
<http://www.kamailioworld.com>
>>> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin --
www.asipto.com
<http://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(a)sipwise.com <mailto:mcapetta@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 <http://www.asipto.com>
>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
> Kamailio World Conference --
www.kamailioworld.com
<http://www.kamailioworld.com>
> Kamailio Advanced Training, Nov 12-14, 2018, in Berlin --
www.asipto.com
<http://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(a)sipwise.com <mailto:mcapetta@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
<http://www.kamailioworld.com>
Kamailio Advanced Training, Nov 12-14, 2018, in Berlin --