DMQ issues and CRITICAL errors
Sergio Charrua via sr-users <[email protected]> Fri, 3 Jul 2026 17:52:15 +0200
| Newsgroups | gmane.comp.voip.ser |
|---|---|
| Message-ID | <CALZWR5xUNgzeK6aLt3OSh-+wTQPVbLXNZz0DituYYmfELtdumg@mail.gmail.com> |
--===============0823366682==
Content-Type: multipart/alternative; boundary="000000000000dde5ae0655b6ead4"
--000000000000dde5ae0655b6ead4
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Hi all,
have a standard HA setup using 2 kamailio nodes (SIP 1 and SIP 2) and a VIP
managed by Keepalid service.
Both kamailio nodes use same configuration and while one is the Active node
(where the VIP is present) the other is Backup node. Not rocket science.
We use DMQ to share dialog data between nodes, using a second IP:Port
address (Node 1 is .126:5062 , Node 2 is .125:5062)
The VIP is .147 and SIP is listened on the VIP at .147:5060
Here is the test scenario:
- SIP 1 (Active node) receives the initial INVITE, requests Routing Engine
for a list of routes (uses EVAPI script who interacts with a REST service)
- call is routed to egress endpoint according to the route list received
- some SIP 183 is replied back and forwarded to ingress endpoint
- a PRACK is received as a reply from the previous SIP 183 and kamailio
forwards to egress side
- *** Kamailio SIP 1 instance is stopped (service kamailio stop) ****
- VIP switches to node SIP 2
- SIP 2 gets a reply SIP 200 OK from egress side (assuming a
retransmission)
- *** CRITICAL error is logged with :
CRITICAL: {1783082372.409470 857991 1
48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}dialog [dlg_hash.c:1276]: next_state_dlg(): bogus event 6 in state 2
for dlg 0x7f4d7c886990 [193061:598258] with clid
'48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209' and tags
'*.*.12.209+2+32486fa4+25838f19' ''
- *** there should be a call to EVAPI script to notify the call was
answered (CALL_CONNECT notification) but there is none ----> Meanwhile i
solved this, and CALL_CONNECT is sent event if there is a CRITICAL event
- call seems to continue perfectly until BYE is received and a EVAPI script
is notified with a CALL_FINISH request
Here are the logs on SIP 1 who received the initial INVITE:
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930200]: INFO:
{1783082368.672371 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: Processing INVITE from *.*.12.209:5242 to sip:+33100001209=
@
*.*.12.137:5242;user=3Dphone
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930200]: INFO:
{1783082368.673719 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: HANDLE_INVITE - suspended transaction for INVITE
INVITE:::{"sip_invite":{"Via":"SIP/2.0/UDP
*.*.12.209:5242;branch=3Dz9hG4bK+bb3831916f972b133610a3eb7d60da343+sip+2+a6=
5dede3","From":"\"+33000007\"
<sip:+33000000012@
*.*.12.107;user=3Dphone>;tag=3D*.*.12.209+2+32486fa4+25838f19","To":"<sip:+=
33100001209@*.*.12.137;user=3Dphone>","CSeq":"1
INVITE","Content-Length":"175","Supported":"timer,histinfo,replaces,
100rel","P-Charging-Vector":"icid-value=3D1a18eec80dbf1bcaa957e9322967a9d7;=
orig-ioi=3DBICS","Contact":"<sip:+33000000012@
*.*.12.209:5242;transport=3Dudp;user=3Dphone>","Content-Type":"application/=
sdp","Call-ID":"48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209","Accept":"appl=
ication/sdp,
application/isup,
application/dtmf,multipart/mixed","Max-Forwards":"68","Session-Expires":"18=
00","Min-SE":"90","P-Asserted-Identity":"\"+33000000012\"
<sip:+33000000012@
*.*.12.107;user=3Dphone>","X-REFERRED-BY":["<sip:[email protected]=
b.microsoft.com:5060
;user=3Dphone>","<sip:[email protected]:5060
;user=3Dphone>"],"X-tgrp":"CloudCom","X-Test":"CC_Outb_23","X-bababa-PID":"=
11283","X-History-Info":["<sip:+380930539504@
*.*.12.107;user=3Dphone;cause=3D408>;index=3D1","<sip:380930539504@
*.*.12.107;user=3Dphone;cause=3D486;transport=3Dudp>;index=3D1.1","<sip:+33=
54806000999@
*.*.12.110:5060?reason=3DSIP%3Bcause%3D302>;index=3D1,<sip:+33969990333@
*.*.12.110:5060;user=3Dphone>;index=3D1.1,<sip:380930539504@
*.*.12.107;user=3Dphone;cause=3D481;transport=3Dudp>;index=3D1.1.1,<sip:334=
444444444444@
*.*.12.107;user=3Dphone;cause=3D481;transport=3Dudp>;index=3D1.1.1.1"],"Div=
ersion":"<
sip:[email protected]
>","Allow":"INVITE,ACK,CANCEL,BYE,REGISTER,SUBSCRIBE,NOTIFY,UPDATE,OPTIONS,=
MESSAGE,PUBLISH","Privacy":"none","Method":"INVITE","Request-URI":"sip:+331=
00001209@
*.*.12.137:5242;user=3Dphone"},"remote_ip_port":"*.*.12.209:5242","local_ip=
_port":"
10.242.17.147:5060
","protocol":"udp","retry":0,"timestamp":"1783082368.672364"}
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930200]: INFO:
{1783082368.673764 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: HANDLE_INVITE - suspended transaction for INVITE /
CALL_ATTEMPT. Index: <null> - Label: <null>
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.749972 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: EVAPIRESPONSE - TRANSACTION 62044|1856782967
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750015 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: EVAPIRESPONSE - Resumed with RESPONSE {"action": "ROUTE",
"routes": [{"tkg_eid": "101253", "crankback_profile": [{"sip_errors":
["403", "500", "503", "408", "cb_to_transit"], "next_tkg_eid": "101254"}],
"dst_uri": "sip:*.*.12.209:5253", "uri":
"sip:+33100001209@*.*.12.209:5253;user=3Dphone",
"headers": {"delete": null, "add": [{"P-Access-Network-Info":
"GSTN;operator-specific-GI=3D\"011921212\";network-provided"}], "from":
{"display": "+33000007", "uri": "sip:+33000000012@*.*.12.107;user=3Dphone"}=
,
"to": {"uri": "sip:+33100001209@*.*.12.209:5253;user=3Dphone"}},
"max_call_duration": 43200}, {"tkg_eid": "101254", "crankback_profile": [],
"dst_uri": "sip:*.*.199.167:5254", "uri":
"sip:+33100001209@*.*.199.167:5254;user=3Dphone",
"headers": {"delete": null, "add": [{"P-Access-Network-Info":
"GSTN;operator-specific-GI=3D\"011921212\";network-provided"}], "from":
{"display": "+33000007", "uri": "sip:+33000000012@*.*.12.107;user=3Dphone"}=
,
"to": {"uri": "sip:+33100001209@*.*.199.167:5254;user=3Dphone"}},
"max_call_duration": 43200}], "retry_on_failure": false,
"max_number_of_crankbacks": 2, "version": "1.0", "method": "INVITE",
"routing": "serial", "call_id": "48c1e14ce80dbdd6beacacda1aa8f79c@
*.*.12.209"}
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750121 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: EVAPIRESPONSE - ROUTE action
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750166 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: EVAPIRESPONSE - NO retry_on_failure FOUND or
retry_on_failure =3D 0 !
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750213 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: EVAPIRESPONSE - retry_on_failure =3D 0
max_number_of_crankbacks =3D 2
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750239 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: JSON_ROUTE_PROCESS - start retry=3D0
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750310 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: JSON_ROUTE_PROCESS - 2 route(s) available -
max_crankbacks=3D2
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750419 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: APPLY_ROUTE_AND_RELAY - idx=3D0 -
ru=3Dsip:+33100001209@*.*.12.209:5253;user=3Dphone
du=3Dsip:*.*.12.209:5253
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750617 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: RELAY - tkg_eid=3D101253 idx=3D0
ru=3Dsip:+33100001209@*.*.12.209:5253;user=3Dphone
du=3Dsip:*.*.12.209:5253
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750726 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<core> [core/kemi.c:155]: sr_kemi_core_log(): modify_invite_headers:
rtjsonValue is empty, undefined or null, trying to get from $var(cur_route)
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.750974 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: PIN_SOCKET - socket is pinned 1
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.751036 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_BRANCH - initializing new branch [1] to
sip:+33100001209@*.*.12.209:5253;user=3Dphone
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO:
{1783082368.751054 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_BRANCH - Starting monitoring counter for endpoint
sip:*.*.12.209:5253 from *.*.17.147:5060 at 1783082368
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO:
{1783082368.753932 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: onreply_route - 100 : INVITE replied from
sip:*.*.12.209:5253 with SIP 100
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO:
{1783082368.753994 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Incoming reply INVITE 100
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO:
{1783082368.754012 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Starting monitoring counter for endpoint
sip:*.*.12.209:5253
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO:
{1783082368.754025 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Forwarding 100 Trying
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO:
{1783082368.754033 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: RESET_FAILURE_COUNTER - resetting failure counter for
sip:*.*.12.209:5253 to 0
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.866708 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: onreply_route - 183 : INVITE replied from
sip:*.*.12.209:5253 with SIP 183
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.866815 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Incoming reply INVITE 183
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.866835 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Starting monitoring counter for endpoint
sip:*.*.12.209:5253
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.866855 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Forwarding 180/183 Session Progress
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.867114 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - setting Ringing Timestamp to
1783082368.866860
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: INFO:
{1783082368.867141 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: RESET_FAILURE_COUNTER - resetting failure counter for
sip:*.*.12.209:5253 to 0
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082368.876888 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
PRACK}<script>: PIN_SOCKET - socket is pinned 1
Jul 3 12:39:28 bl1649 /usr/local/sbin/kamailio[930201]: INFO:
{1783082368.882525 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
PRACK}<script>: onreply_route - 200 : PRACK replied from
sip:*.*.12.209:5253 with SIP 200
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.884679 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: onreply_route - 180 : INVITE replied from
sip:*.*.12.209:5253 with SIP 180
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.884771 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Incoming reply INVITE 180
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.884790 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Starting monitoring counter for endpoint
sip:*.*.12.209:5253
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.884815 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - Forwarding 180/183 Session Progress
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.885326 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: MANAGE_REPLY - setting Ringing Timestamp to
1783082369.884822
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930202]: INFO:
{1783082369.885357 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: RESET_FAILURE_COUNTER - resetting failure counter for
sip:*.*.12.209:5253 to 0
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930201]: INFO:
{1783082369.892923 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
PRACK}<script>: PIN_SOCKET - socket is pinned 1
Jul 3 12:39:29 bl1649 /usr/local/sbin/kamailio[930199]: INFO:
{1783082369.899687 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
PRACK}<script>: onreply_route - 200 : PRACK replied from
sip:*.*.12.209:5253 with SIP 200
These are the logs from SIP 2 after the VIP has switched:
Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857997]: INFO:
{1783082372.401717 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
INVITE}<script>: onreply_route - 200 : INVITE replied from
sip:*.*.12.209:5253 with SIP 200
Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: INFO:
{1783082372.409421 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}<script>: TRACK_ACK - saving ACK timestamp 1783082372.409075
*Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: CRITICAL:
{1783082372.409470 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}dialog [dlg_hash.c:1276]: next_state_dlg(): bogus event 6 in state 2
for dlg 0x7f4d7c886990 [193061:598258] with clid
'48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209' and tags
'*.*.12.209+2+32486fa4+25838f19' ''*
Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: INFO:
{1783082372.409553 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}<script>: PIN_SOCKET - stored dlg_sock=3Dudp:10.242.17.147:5060
Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: INFO:
{1783082372.409604 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}<script>: PIN_SOCKET - forcing <udp:10.242.17.147:5060> (recv udp:
10.242.17.147:5060)
Jul 3 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: INFO:
{1783082372.409631 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
ACK}<script>: PIN_SOCKET - socket is pinned 0
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.429353 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: WITHINDLG - method is BYE - going to TRACK_BYE
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.429883 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: TRACK_BYE - CALLED side finished the call
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.429903 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: TRACK_BYE - setting ts_bye_usec 1783082382.429388 and
bye_originator *.*.12.209 sent from CALLED
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: WARNING:
{1783082382.429954 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: WITHINDLG - BYE detected
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.429982 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: PIN_SOCKET - socket is pinned 1
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.430041 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: MANAGE_BRANCH - initializing new branch [0] to
sip:+33000000012@*.*.12.209:5242;transport=3Dudp;user=3Dphone
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO:
{1783082382.430081 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: MANAGE_BRANCH - Starting monitoring counter for endpoint
sip:*.*.12.209:5242 from 10.242.17.147:5060 at 1783082382
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.437745 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: onreply_route - 200 : BYE replied from sip:*.*.12.209:5242
with SIP 200
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: WARNING:
{1783082382.437780 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: onreply_route - BYE detected
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.437800 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: onreply_route - BYE and response received
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438136 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: TRACK_BYE_200 - setting ts_bye_200ok_usec value
1783082382.437886
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438162 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - checking call status t_check_status(200) =
=3D
200 ; method =3D BYE
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438392 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - crankback_history set to []
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438441 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - processing BYE, checking if call was
answered with t_check_status(200) =3D 200
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438503 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - processing BYE, finished_by set to CALLED
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438549 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - processing BYE, bye_time set to
1783082382.429388
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438597 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - processing BYE, invite_ack_time set to
1783082372.409075
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438655 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - processing BYE, bye_200_time set to
1783082382.437886 - $var(cached_ack_time)=3D0;
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438694 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: EV_MAKE_KEY - building event key for CALL_FINISH with hint
BYE|-1
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438924 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: EV_GUARD_ONCE - first time (CALL_FINISH)
key=3D[48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209|CALL_FINISH] -> SEND
Jul 3 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO:
{1783082382.438964 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209
BYE}<script>: SEND_CALL_STATUS - sending
CALL_FINISH:{"call_id":"48c1e14ce80dbdd6beacacda1aa8f79c@
*.*.12.209","from":"<sip:+33100001209@*.*.12.209:5253;user=3Dphone>;tag=3Ds=
ip+2+b8f70030+683bf4af","to":"+33000007
<sip:+33000000012@
*.*.12.107;user=3Dphone>;tag=3D*.*.12.209+2+32486fa4+25838f19","timestamp":=
"1783082382.438283","tkg_eid":"101253","remote_ip_port":"*.*.12.209:5242","=
local_ip_port":"*.*.17.147:5060","crankback_history":[],"finished_by":"CALL=
ED","bye_time":"1783082382.429388","invite_ack_time":"1783082372.409075","b=
ye_200_time":"1783082382.437886","type":"CALL_FINISH"}
My question is related with the lines above that I prefixed with *** and to
log lines marked with orange background and bold fonts: I understand the
CRITICAL error on SIP 2 is due to the Finite State Machine (FSM) that does
not expect a ACK/PRACK or 200 OK at this point, but I wonder if this is an
issue for processing calls?
We have been testing at 2 CAPS and this issue happens quite often. We are
aiming to 2000 CAPS minimum, so the issue will be exponential and we can't
go live like this, at least without knowing if there are any effects on
calls.
Thanks in advance.
Atenciosamente / Kind Regards / Cordialement / Un saludo,
*S=C3=A9rgio Charrua*
*www.kahea.ai <http://www.kahea.ai> / www.voip.pt <http://www.voip.pt>*
*OpenTelecom* - Consulting for Telecoms, Lda
Tel.: +351 <callto:+351+91+104+12+66>91 631 11 44
Email : *[email protected] <[email protected]>*
This message and any files or documents attached are strictly confidential
or otherwise legally protected.
It is intended only for the individual or entity named. If you are not the
named addressee or have received this email in error, please inform the
sender immediately, delete it from your system and do not copy or disclose
it or its contents or use it for any purpose. Please also note that
transmission cannot be guaranteed to be secure or error-free.
--000000000000dde5ae0655b6ead4
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
<div dir=3D"ltr"><div>Hi all,<br clear=3D"all"></div><div><br></div><div>ha=
ve a standard HA setup using 2 kamailio nodes (SIP 1 and SIP 2) and a VIP m=
anaged by Keepalid service.</div><div>Both kamailio nodes use same configur=
ation and while one is the Active node (where the VIP is present) the other=
is Backup node. Not rocket science.</div><div>We use DMQ to share dialog d=
ata between nodes, using a second IP:Port address (Node 1 is .126:5062 , No=
de 2 is .125:5062)</div><div>The VIP is .147 and=C2=A0<span style=3D"backgr=
ound-color:transparent">SIP is listened on the VIP at .147:5060</span></div=
><div><br></div><div>Here is the test scenario:</div><div>- SIP 1 (Active n=
ode) receives the initial INVITE, requests Routing Engine for a list of rou=
tes (uses EVAPI script who interacts with a REST service)</div><div>- call =
is routed to egress endpoint according to the route list received</div><div=
>- some SIP 183 is replied back and forwarded to ingress endpoint</div><div=
>- a PRACK is received as a reply from the previous SIP 183 and kamailio fo=
rwards to egress side</div><div>- *** Kamailio SIP 1 instance is stopped (s=
ervice kamailio stop) ****</div><div>- VIP switches to node SIP 2</div><div=
>- SIP 2 gets a reply SIP 200 OK from egress side (assuming a retransmissio=
n)=C2=A0</div><div>- *** CRITICAL error is logged with :=C2=A0</div><div>CR=
ITICAL: {1783082372.409470 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12=
.209 ACK}dialog [dlg_hash.c:1276]: next_state_dlg(): bogus event 6 in state=
2 for dlg 0x7f4d7c886990 [193061:598258] with clid '48c1e14ce80dbdd6be=
acacda1aa8f79c@*.*.12.209' and tags '*.*.12.209+2+32486fa4+25838f19=
' ''<br></div><div>- *** there should be a call to EVAPI script=
to notify the call was answered (CALL_CONNECT notification) but there is n=
one=C2=A0 ----> Meanwhile i solved this, and CALL_CONNECT is sent event =
if there is a CRITICAL event</div><div>- call seems to continue perfectly u=
ntil BYE is received and a EVAPI script is notified with a CALL_FINISH requ=
est</div><div><br></div><div>Here are the logs on SIP 1 who received the in=
itial INVITE:</div><div><font face=3D"monospace">Jul =C2=A03 12:39:28 bl164=
9 /usr/local/sbin/kamailio[930200]: INFO: {1783082368.672371 930193 1 48c1e=
14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: Processing IN=
VITE from *.*.12.209:5242 to sip:+33100001209@*.*.12.137:5242;user=3Dphone<=
br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930200]: INFO: {178=
3082368.673719 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}=
<script>: HANDLE_INVITE - suspended transaction for INVITE INVITE:::{=
"sip_invite":{"Via":"SIP/2.0/UDP *.*.12.209:5242;b=
ranch=3Dz9hG4bK+bb3831916f972b133610a3eb7d60da343+sip+2+a65dede3",&quo=
t;From":"\"+33000007\" <sip:+33000000012@*.*.12.107;=
user=3Dphone>;tag=3D*.*.12.209+2+32486fa4+25838f19","To":=
"<sip:+33100001209@*.*.12.137;user=3Dphone>","CSeq&quo=
t;:"1 INVITE","Content-Length":"175","Su=
pported":"timer,histinfo,replaces, 100rel","P-Charging-=
Vector":"icid-value=3D1a18eec80dbf1bcaa957e9322967a9d7;orig-ioi=
=3DBICS","Contact":"<sip:+33000000012@*.*.12.209:524=
2;transport=3Dudp;user=3Dphone>","Content-Type":"app=
lication/sdp","Call-ID":"48c1e14ce80dbdd6beacacda1aa8f7=
9c@*.*.12.209","Accept":"application/sdp, application/i=
sup, application/dtmf,multipart/mixed","Max-Forwards":"=
68","Session-Expires":"1800","Min-SE":&q=
uot;90","P-Asserted-Identity":"\"+33000000012\&quo=
t; <sip:+33000000012@*.*.12.107;user=3Dphone>","X-REFERRED-=
BY":["<sip:[email protected]:5060;user=
=3Dphone>","<sip:[email protected]:=
5060;user=3Dphone>"],"X-tgrp":"CloudCom","=
X-Test":"CC_Outb_23","X-bababa-PID":"11283&qu=
ot;,"X-History-Info":["<sip:+380930539504@*.*.12.107;user=
=3Dphone;cause=3D408>;index=3D1","<sip:380930539504@*.*.12.=
107;user=3Dphone;cause=3D486;transport=3Dudp>;index=3D1.1","&l=
t;sip:+3354806000999@*.*.12.110:5060?reason=3DSIP%3Bcause%3D302>;index=
=3D1,<sip:+33969990333@*.*.12.110:5060;user=3Dphone>;index=3D1.1,<=
sip:380930539504@*.*.12.107;user=3Dphone;cause=3D481;transport=3Dudp>;in=
dex=3D1.1.1,<sip:334444444444444@*.*.12.107;user=3Dphone;cause=3D481;tra=
nsport=3Dudp>;index=3D1.1.1.1"],"Diversion":"<<a =
href=3D"mailto:sip%3A%[email protected]">sip:[email protected]</a>>=
","Allow":"INVITE,ACK,CANCEL,BYE,REGISTER,SUBSCRIBE,NOT=
IFY,UPDATE,OPTIONS,MESSAGE,PUBLISH","Privacy":"none&quo=
t;,"Method":"INVITE","Request-URI":"sip:=
+33100001209@*.*.12.137:5242;user=3Dphone"},"remote_ip_port"=
:"*.*.12.209:5242","local_ip_port":"<a href=3D"htt=
p://10.242.17.147:5060">10.242.17.147:5060</a>","protocol":&=
quot;udp","retry":0,"timestamp":"1783082368.6=
72364"}<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930200=
]: INFO: {1783082368.673764 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.1=
2.209 INVITE}<script>: HANDLE_INVITE - suspended transaction for INVI=
TE / CALL_ATTEMPT. Index: <null> - Label: <null><br>Jul =C2=A03=
12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO: {1783082368.749972=
930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>=
: EVAPIRESPONSE - TRANSACTION 62044|1856782967<br>Jul =C2=A03 12:39:28 bl16=
49 /usr/local/sbin/kamailio[930227]: INFO: {1783082368.750015 930193 1 48c1=
e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: EVAPIRESPONS=
E - Resumed with RESPONSE {"action": "ROUTE", "rou=
tes": [{"tkg_eid": "101253", "crankback_profi=
le": [{"sip_errors": ["403", "500", &quo=
t;503", "408", "cb_to_transit"], "next_tkg_ei=
d": "101254"}], "dst_uri": "sip:*.*.12.209:52=
53", "uri": "sip:+33100001209@*.*.12.209:5253;user=3Dph=
one", "headers": {"delete": null, "add":=
[{"P-Access-Network-Info": "GSTN;operator-specific-GI=3D\&q=
uot;011921212\";network-provided"}], "from": {"dis=
play": "+33000007", "uri": "sip:+33000000012@=
*.*.12.107;user=3Dphone"}, "to": {"uri": "sip=
:+33100001209@*.*.12.209:5253;user=3Dphone"}}, "max_call_duration=
": 43200}, {"tkg_eid": "101254", "crankback_p=
rofile": [], "dst_uri": "sip:*.*.199.167:5254", &q=
uot;uri": "sip:+33100001209@*.*.199.167:5254;user=3Dphone", =
"headers": {"delete": null, "add": [{"P-=
Access-Network-Info": "GSTN;operator-specific-GI=3D\"0119212=
12\";network-provided"}], "from": {"display":=
"+33000007", "uri": "sip:+33000000012@*.*.12.107;=
user=3Dphone"}, "to": {"uri": "sip:+331000012=
09@*.*.199.167:5254;user=3Dphone"}}, "max_call_duration": 43=
200}], "retry_on_failure": false, "max_number_of_crankbacks&=
quot;: 2, "version": "1.0", "method": "I=
NVITE", "routing": "serial", "call_id": =
"48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209"}<br>Jul =C2=A03 12:=
39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO: {1783082368.750121 930=
193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: EV=
APIRESPONSE - ROUTE action<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/k=
amailio[930227]: INFO: {1783082368.750166 930193 1 48c1e14ce80dbdd6beacacda=
1aa8f79c@*.*.12.209 INVITE}<script>: EVAPIRESPONSE - NO retry_on_fail=
ure FOUND or retry_on_failure =3D 0 !<br>Jul =C2=A03 12:39:28 bl1649 /usr/l=
ocal/sbin/kamailio[930227]: INFO: {1783082368.750213 930193 1 48c1e14ce80db=
dd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: EVAPIRESPONSE - retry=
_on_failure =3D 0 max_number_of_crankbacks =3D 2<br>Jul =C2=A03 12:39:28 bl=
1649 /usr/local/sbin/kamailio[930227]: INFO: {1783082368.750239 930193 1 48=
c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: JSON_ROUTE=
_PROCESS - start =C2=A0retry=3D0<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/=
sbin/kamailio[930227]: INFO: {1783082368.750310 930193 1 48c1e14ce80dbdd6be=
acacda1aa8f79c@*.*.12.209 INVITE}<script>: JSON_ROUTE_PROCESS - 2 rou=
te(s) available - max_crankbacks=3D2<br>Jul =C2=A03 12:39:28 bl1649 /usr/lo=
cal/sbin/kamailio[930227]: INFO: {1783082368.750419 930193 1 48c1e14ce80dbd=
d6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: APPLY_ROUTE_AND_RELAY =
- idx=3D0 - ru=3Dsip:+33100001209@*.*.12.209:5253;user=3Dphone =C2=A0du=3Ds=
ip:*.*.12.209:5253<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[=
930227]: INFO: {1783082368.750617 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c=
@*.*.12.209 INVITE}<script>: RELAY - tkg_eid=3D101253 idx=3D0 =C2=A0r=
u=3Dsip:+33100001209@*.*.12.209:5253;user=3Dphone =C2=A0du=3Dsip:*.*.12.209=
:5253<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO=
: {1783082368.750726 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 I=
NVITE}<core> [core/kemi.c:155]: sr_kemi_core_log(): modify_invite_hea=
ders: rtjsonValue is empty, undefined or null, trying to get from $var(cur_=
route)<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930227]: INF=
O: {1783082368.750974 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 =
INVITE}<script>: PIN_SOCKET - socket is pinned 1<br>Jul =C2=A03 12:39=
:28 bl1649 /usr/local/sbin/kamailio[930227]: INFO: {1783082368.751036 93019=
3 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: MANA=
GE_BRANCH - initializing new branch [1] to sip:+33100001209@*.*.12.209:5253=
;user=3Dphone<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[93022=
7]: INFO: {1783082368.751054 930193 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.=
12.209 INVITE}<script>: MANAGE_BRANCH - Starting monitoring counter f=
or endpoint sip:*.*.12.209:5253 from *.*.17.147:5060 at 1783082368<br>Jul =
=C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO: {1783082368=
.753932 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<scr=
ipt>: onreply_route - 100 : INVITE replied from sip:*.*.12.209:5253 with=
SIP 100<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: I=
NFO: {1783082368.753994 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.20=
9 INVITE}<script>: MANAGE_REPLY - Incoming reply INVITE 100<br>Jul =
=C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO: {1783082368=
.754012 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<scr=
ipt>: MANAGE_REPLY - Starting monitoring counter for endpoint sip:*.*.12=
.209:5253<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: =
INFO: {1783082368.754025 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.2=
09 INVITE}<script>: MANAGE_REPLY - Forwarding 100 Trying<br>Jul =C2=
=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930196]: INFO: {1783082368.75=
4033 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script=
>: RESET_FAILURE_COUNTER - resetting failure counter for sip:*.*.12.209:=
5253 to 0<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: =
INFO: {1783082368.866708 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.2=
09 INVITE}<script>: onreply_route - 183 : INVITE replied from sip:*.*=
.12.209:5253 with SIP 183<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/ka=
mailio[930195]: INFO: {1783082368.866815 930193 2 48c1e14ce80dbdd6beacacda1=
aa8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - Incoming reply INV=
ITE 183<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930195]: IN=
FO: {1783082368.866835 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209=
INVITE}<script>: MANAGE_REPLY - Starting monitoring counter for endp=
oint sip:*.*.12.209:5253<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kam=
ailio[930195]: INFO: {1783082368.866855 930193 2 48c1e14ce80dbdd6beacacda1a=
a8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - Forwarding 180/183 =
Session Progress<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[93=
0195]: INFO: {1783082368.867114 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*=
.*.12.209 INVITE}<script>: MANAGE_REPLY - setting Ringing Timestamp t=
o 1783082368.866860<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio=
[930195]: INFO: {1783082368.867141 930193 2 48c1e14ce80dbdd6beacacda1aa8f79=
c@*.*.12.209 INVITE}<script>: RESET_FAILURE_COUNTER - resetting failu=
re counter for sip:*.*.12.209:5253 to 0<br>Jul =C2=A03 12:39:28 bl1649 /usr=
/local/sbin/kamailio[930202]: INFO: {1783082368.876888 930193 1 48c1e14ce80=
dbdd6beacacda1aa8f79c@*.*.12.209 PRACK}<script>: PIN_SOCKET - socket =
is pinned 1<br>Jul =C2=A03 12:39:28 bl1649 /usr/local/sbin/kamailio[930201]=
: INFO: {1783082368.882525 930193 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12=
.209 PRACK}<script>: onreply_route - 200 : PRACK replied from sip:*.*=
.12.209:5253 with SIP 200<br>Jul =C2=A03 12:39:29 bl1649 /usr/local/sbin/ka=
mailio[930202]: INFO: {1783082369.884679 930193 2 48c1e14ce80dbdd6beacacda1=
aa8f79c@*.*.12.209 INVITE}<script>: onreply_route - 180 : INVITE repl=
ied from sip:*.*.12.209:5253 with SIP 180<br>Jul =C2=A03 12:39:29 bl1649 /u=
sr/local/sbin/kamailio[930202]: INFO: {1783082369.884771 930193 2 48c1e14ce=
80dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - In=
coming reply INVITE 180<br>Jul =C2=A03 12:39:29 bl1649 /usr/local/sbin/kama=
ilio[930202]: INFO: {1783082369.884790 930193 2 48c1e14ce80dbdd6beacacda1aa=
8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - Starting monitoring =
counter for endpoint sip:*.*.12.209:5253<br>Jul =C2=A03 12:39:29 bl1649 /us=
r/local/sbin/kamailio[930202]: INFO: {1783082369.884815 930193 2 48c1e14ce8=
0dbdd6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - For=
warding 180/183 Session Progress<br>Jul =C2=A03 12:39:29 bl1649 /usr/local/=
sbin/kamailio[930202]: INFO: {1783082369.885326 930193 2 48c1e14ce80dbdd6be=
acacda1aa8f79c@*.*.12.209 INVITE}<script>: MANAGE_REPLY - setting Rin=
ging Timestamp to 1783082369.884822<br>Jul =C2=A03 12:39:29 bl1649 /usr/loc=
al/sbin/kamailio[930202]: INFO: {1783082369.885357 930193 2 48c1e14ce80dbdd=
6beacacda1aa8f79c@*.*.12.209 INVITE}<script>: RESET_FAILURE_COUNTER -=
resetting failure counter for sip:*.*.12.209:5253 to 0<br>Jul =C2=A03 12:3=
9:29 bl1649 /usr/local/sbin/kamailio[930201]: INFO: {1783082369.892923 9301=
93 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 PRACK}<script>: PIN_=
SOCKET - socket is pinned 1<br>Jul =C2=A03 12:39:29 bl1649 /usr/local/sbin/=
kamailio[930199]: INFO: {1783082369.899687 930193 2 48c1e14ce80dbdd6beacacd=
a1aa8f79c@*.*.12.209 PRACK}<script>: onreply_route - 200 : PRACK repl=
ied from sip:*.*.12.209:5253 with SIP 200</font></div><div><br></div><div>T=
hese are the logs from SIP 2 after the VIP has switched:</div><div><br><fon=
t face=3D"monospace">Jul =C2=A03 12:39:32 bl1650 /usr/local/sbin/kamailio[8=
57997]: INFO: {1783082372.401717 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@=
*.*.12.209 INVITE}<script>: onreply_route - 200 : INVITE replied from=
sip:*.*.12.209:5253 with SIP 200<br>Jul =C2=A03 12:39:32 bl1650 /usr/local=
/sbin/kamailio[857996]: INFO: {1783082372.409421 857991 1 48c1e14ce80dbdd6b=
eacacda1aa8f79c@*.*.12.209 ACK}<script>: TRACK_ACK - saving ACK times=
tamp 1783082372.409075<br><span style=3D"background-color:rgb(255,153,0)"><=
b>Jul =C2=A03 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: CRITICAL: {=
1783082372.409470 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 ACK}=
dialog [dlg_hash.c:1276]: next_state_dlg(): bogus event 6 in state 2 for dl=
g 0x7f4d7c886990 [193061:598258] with clid '48c1e14ce80dbdd6beacacda1aa=
8f79c@*.*.12.209' and tags '*.*.12.209+2+32486fa4+25838f19' =
9;'</b></span><br>Jul =C2=A03 12:39:32 bl1650 /usr/local/sbin/kamailio[=
857996]: INFO: {1783082372.409553 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c=
@*.*.12.209 ACK}<script>: PIN_SOCKET - stored dlg_sock=3Dudp:<a href=
=3D"http://10.242.17.147:5060">10.242.17.147:5060</a><br>Jul =C2=A03 12:39:=
32 bl1650 /usr/local/sbin/kamailio[857996]: INFO: {1783082372.409604 857991=
1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 ACK}<script>: PIN_SOCK=
ET - forcing <udp:<a href=3D"http://10.242.17.147:5060">10.242.17.147:50=
60</a>> (recv udp:<a href=3D"http://10.242.17.147:5060">10.242.17.147:50=
60</a>)<br>Jul =C2=A03 12:39:32 bl1650 /usr/local/sbin/kamailio[857996]: IN=
FO: {1783082372.409631 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209=
ACK}<script>: PIN_SOCKET - socket is pinned 0<br>Jul =C2=A03 12:39:4=
2 bl1650 /usr/local/sbin/kamailio[858001]: INFO: {1783082382.429353 857991 =
1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: WITHINDLG=
- method is BYE - going to TRACK_BYE<br>Jul =C2=A03 12:39:42 bl1650 /usr/l=
ocal/sbin/kamailio[858001]: INFO: {1783082382.429883 857991 1 48c1e14ce80db=
dd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: TRACK_BYE - CALLED side =
finished the call<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[8=
58001]: INFO: {1783082382.429903 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@=
*.*.12.209 BYE}<script>: TRACK_BYE - setting ts_bye_usec 1783082382.4=
29388 and bye_originator *.*.12.209 sent from CALLED<br>Jul =C2=A03 12:39:4=
2 bl1650 /usr/local/sbin/kamailio[858001]: WARNING: {1783082382.429954 8579=
91 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: WITHIN=
DLG - BYE detected<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[=
858001]: INFO: {1783082382.429982 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c=
@*.*.12.209 BYE}<script>: PIN_SOCKET - socket is pinned 1<br>Jul =C2=
=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[858001]: INFO: {1783082382.43=
0041 857991 1 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>=
;: MANAGE_BRANCH - initializing new branch [0] to sip:+33000000012@*.*.12.2=
09:5242;transport=3Dudp;user=3Dphone<br>Jul =C2=A03 12:39:42 bl1650 /usr/lo=
cal/sbin/kamailio[858001]: INFO: {1783082382.430081 857991 1 48c1e14ce80dbd=
d6beacacda1aa8f79c@*.*.12.209 BYE}<script>: MANAGE_BRANCH - Starting =
monitoring counter for endpoint sip:*.*.12.209:5242 from <a href=3D"http://=
10.242.17.147:5060">10.242.17.147:5060</a> at 1783082382<br>Jul =C2=A03 12:=
39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {1783082382.437745 857=
991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: onrep=
ly_route - 200 : BYE replied from sip:*.*.12.209:5242 with SIP 200<br>Jul =
=C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: WARNING: {1783082=
382.437780 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<scr=
ipt>: onreply_route - BYE detected<br>Jul =C2=A03 12:39:42 bl1650 /usr/l=
ocal/sbin/kamailio[857999]: INFO: {1783082382.437800 857991 2 48c1e14ce80db=
dd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: onreply_route - BYE and =
response received<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[8=
57999]: INFO: {1783082382.438136 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@=
*.*.12.209 BYE}<script>: TRACK_BYE_200 - setting ts_bye_200ok_usec va=
lue 1783082382.437886<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamail=
io[857999]: INFO: {1783082382.438162 857991 2 48c1e14ce80dbdd6beacacda1aa8f=
79c@*.*.12.209 BYE}<script>: SEND_CALL_STATUS - checking call status =
t_check_status(200) =3D 200 ; method =3D BYE<br>Jul =C2=A03 12:39:42 bl1650=
/usr/local/sbin/kamailio[857999]: INFO: {1783082382.438392 857991 2 48c1e1=
4ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: SEND_CALL_STATUS =
- crankback_history set to []<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbi=
n/kamailio[857999]: INFO: {1783082382.438441 857991 2 48c1e14ce80dbdd6beaca=
cda1aa8f79c@*.*.12.209 BYE}<script>: SEND_CALL_STATUS - processing BY=
E, checking if call was answered with t_check_status(200) =3D 200<br>Jul =
=C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {1783082382=
.438503 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script=
>: SEND_CALL_STATUS - processing BYE, finished_by set to CALLED<br>Jul =
=C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {1783082382=
.438549 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script=
>: SEND_CALL_STATUS - processing BYE, bye_time set to 1783082382.429388<=
br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {178=
3082382.438597 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<=
;script>: SEND_CALL_STATUS - processing BYE, invite_ack_time set to 1783=
082372.409075<br>Jul =C2=A03 12:39:42 bl1650 /usr/local/sbin/kamailio[85799=
9]: INFO: {1783082382.438655 857991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.=
12.209 BYE}<script>: SEND_CALL_STATUS - processing BYE, bye_200_time =
set to 1783082382.437886 - $var(cached_ack_time)=3D0;<br>Jul =C2=A03 12:39:=
42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {1783082382.438694 857991=
2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: EV_MAKE_=
KEY - building event key for CALL_FINISH with hint BYE|-1<br>Jul =C2=A03 12=
:39:42 bl1650 /usr/local/sbin/kamailio[857999]: INFO: {1783082382.438924 85=
7991 2 48c1e14ce80dbdd6beacacda1aa8f79c@*.*.12.209 BYE}<script>: EV_G=
UARD_ONCE - first time (CALL_FINISH) key=3D[48c1e14ce80dbdd6beacacda1aa8f79=
c@*.*.12.209|CALL_FINISH] -> SEND<br>Jul =C2=A03 12:39:42 bl1650 /usr/lo=
cal/sbin/kamailio[857999]: INFO: {1783082382.438964 857991 2 48c1e14ce80dbd=
d6beacacda1aa8f79c@*.*.12.209 BYE}<script>: SEND_CALL_STATUS - sendin=
g CALL_FINISH:{"call_id":"48c1e14ce80dbdd6beacacda1aa8f79c@*=
.*.12.209","from":"<sip:+33100001209@*.*.12.209:5253=
;user=3Dphone>;tag=3Dsip+2+b8f70030+683bf4af","to":"=
+33000007 <sip:+33000000012@*.*.12.107;user=3Dphone>;tag=3D*.*.12.209=
+2+32486fa4+25838f19","timestamp":"1783082382.438283&qu=
ot;,"tkg_eid":"101253","remote_ip_port":"=
;*.*.12.209:5242","local_ip_port":"*.*.17.147:5060"=
;,"crankback_history":[],"finished_by":"CALLED&quo=
t;,"bye_time":"1783082382.429388","invite_ack_time=
":"1783082372.409075","bye_200_time":"1783082=
382.437886","type":"CALL_FINISH"}</font><br></div>=
<div><br></div><div>My question is related with the lines above that I pref=
ixed with *** and to log lines marked with orange background and bold fonts=
: I understand the CRITICAL error on SIP 2 is due to the Finite State Machi=
ne (FSM) that does not expect a ACK/PRACK or 200 OK at this point, but I wo=
nder if this is an issue for processing calls?</div><div><span style=3D"bac=
kground-color:transparent"><br></span></div><div><span style=3D"background-=
color:transparent">We have been testing at 2 CAPS and this issue happens qu=
ite often. We are aiming </span>to 2000 CAPS minimum,<span style=3D"backgro=
und-color:transparent"> so </span>the<span style=3D"background-color:transp=
arent"> issue will </span>be exponential<span style=3D"background-color:tra=
nsparent"> and we can't go live like this, at least without knowing if =
there are any effects on calls.</span></div><div><br></div><div>Thanks in a=
dvance.</div><div><br></div><div><br></div><div><div dir=3D"ltr" class=3D"g=
mail_signature" data-smartmail=3D"gmail_signature"><div dir=3D"ltr"><div di=
r=3D"ltr"><div dir=3D"ltr"><div dir=3D"ltr"><div dir=3D"ltr"><p style=3D"co=
lor:rgb(0,0,0);margin:0px;font-family:Calibri,sans-serif;background-color:r=
gb(253,253,253)"><span style=3D"font-family:Arial,sans-serif">Atenciosament=
e / Kind Regards / Cordialement / Un saludo,</span></p><p style=3D"color:rg=
b(0,0,0);margin:0px;font-family:Calibri,sans-serif;background-color:rgb(253=
,253,253)"><b><span style=3D"font-family:Arial,sans-serif"><br></span></b><=
/p><p style=3D"color:rgb(0,0,0);margin:0px;font-family:Calibri,sans-serif;b=
ackground-color:rgb(253,253,253)"><b><span style=3D"font-family:Arial,sans-=
serif">S=C3=A9rgio Charrua</span></b></p><div><div dir=3D"ltr"><p style=3D"=
font-size:11pt;color:rgb(0,0,0);margin:0px;font-family:Calibri,sans-serif;b=
ackground-color:rgb(253,253,253)"><b><span style=3D"font-size:9pt;font-fami=
ly:Arial,sans-serif;color:red"><span style=3D"color:rgb(0,0,0)"></span><spa=
n style=3D"color:rgb(51,102,255)"><a href=3D"http://www.kahea.ai" target=3D=
"_blank">www.kahea.ai</a> /=C2=A0<a href=3D"http://www.voip.pt" target=3D"_=
blank">www.voip.pt</a></span></span></b></p><p style=3D"margin:0px;font-fam=
ily:Calibri,sans-serif;background-color:rgb(253,253,253)"><span style=3D"fo=
nt-family:Arial,sans-serif"><span style=3D"font-size:12px"><font color=3D"#=
000000"><b>OpenTelecom</b> - Consulting for Telecoms, Lda</font><br></span>=
</span><span style=3D"color:rgb(0,0,0);font-size:x-small;font-family:Arial,=
sans-serif">Tel.:=C2=A0<span style=3D"color:rgb(51,102,153)"><a href=3D"cal=
lto:+351+91+104+12+66" style=3D"color:rgb(51,102,153);text-decoration:none"=
target=3D"_blank">+351=C2=A0</a>91 631 11 44<br></span></span><font color=
=3D"#000000" size=3D"1"><span style=3D"font-family:"Times New Roman&qu=
ot;,serif"></span></font></p><p style=3D"font-size:11pt;color:rgb(0,0,0);ma=
rgin:0px;font-family:Calibri,sans-serif;background-color:rgb(253,253,253)">=
<span style=3D"font-size:x-small"><span style=3D"font-family:Arial,sans-ser=
if;color:rgb(187,187,187)"><span style=3D"color:rgb(128,128,128)">Email :=
=C2=A0<strong><a href=3D"mailto:[email protected]" style=3D"color:rgb(=
17,85,204)" target=3D"_blank">[email protected]</a></strong></span><br=
></span></span></p><table border=3D"0" cellspacing=3D"0" cellpadding=3D"0" =
width=3D"650" style=3D"width:487.5pt">
<tbody><tr>
<td style=3D"padding:0cm">
<p class=3D"MsoNormal"><span lang=3D"EN-US" style=3D"font-family:"Vo=
dafone Rg";color:rgb(204,204,204)">This message
and any files or documents attached are strictly confidential or otherwis=
e
legally protected.=C2=A0</span></p><p class=3D"MsoNormal"><span lang=3D"E=
N-US" style=3D"font-family:"Vodafone Rg";color:rgb(204,204,204)">=
It is intended only for the individual or entity named. If
you are not the named addressee or have received this email in error, ple=
ase
inform the sender immediately, delete it from your system and do not copy=
or
disclose it or its contents or use it for any purpose. Please also note t=
hat
transmission cannot be guaranteed to be secure or error-free. </span><spa=
n lang=3D"EN-US" style=3D"font-family:"Times New Roman",serif"><s=
pan></span></span></p>
</td>
</tr>
</tbody></table><p style=3D"color:rgb(0,0,0);margin:0px;font-family:Calibri=
,sans-serif;background-color:rgb(253,253,253)">
<span style=3D"font-family:"Times New Roman",serif"></span></p><p=
class=3D"MsoNormal"><span lang=3D"EN-US">=C2=A0</span></p><p style=3D"colo=
r:rgb(0,0,0);margin:0px;font-family:Calibri,sans-serif;background-color:rgb=
(253,253,253)">=C2=A0</p></div></div><div style=3D"font-size:small"><br><br=
></div></div></div></div></div></div></div></div></div>
--000000000000dde5ae0655b6ead4--
--===============0823366682==
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions -- [email protected]
To unsubscribe send an email to [email protected]
Important: keep the mailing list in the recipients, do not reply only to the sender!
--===============0823366682==--