[Spce-user] call drop immediately

Theo axessofficetheo at gmail.com
Mon Sep 9 05:19:25 EDT 2013


Hi

I have an issue at one client who have their own asterisk box. Some calls
drop immediately. We cannot reproduce the issue when testing, but yet there
are too many instances of this happening. Eventually we picked up on one,
proxy log below. I have in the meantime set the sems debug level to 3 to
hopefully see more (what should the default level be by the way?) but is
there anything in this log that is a giveaway? I see a bye coming from sems
I think, but why?

Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: New
request - M=INVITE
R=sip:27110254990 at xxx.xx.xxx.xxxF=sip:27835195154 at yyy.yy.yyy.yyyT=sip:27110254990 at xxx.xx.xxx.xxxIP=yyy.yy.yyy.yyy:5060
(
127.0.0.1:5060) ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Call from
PSTN - R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Load peer
preferences for peer host '15' -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Load
dialplan IDs for peer host '15' -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Fetched
dialplan IDs caller_in='<null>', callee_in='<null>' -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Use
'P-NGCP-Src-Ip' for CDR IP -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Dialog
set mark total -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Dialog
set mark peer to '15' -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: IP
authorization for caller not provisioned, allow call -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>:
User-Provided CLI '27835195154' taken from From-User -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>:
Network-Provided CLI '27835195154' taken from From-User -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
'27835195154 at yyy.yy.yyy.yyy' as initiating user-provided CLI -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
'27835195154 at yyy.yy.yyy.yyy' as initiating network-provided CLI -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Searching
for callee - R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Skipping
internal services for unauthenticated call -
R=sip:27110254990 at xxx.xx.xxx.xxxID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Callee
was aliased with base '27110254990' -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Clear
callee preferences -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Callee is
local, uuid='f2bdc2a5-b277-49c6-bc5f-2913cdc7e874' - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Check
Administrative NCOS level -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Check
User NCOS level -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Checking
URI domain.com'maodi1 at maodi.sw1.domain.com' and CLI '27110254990' against
block out lists -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Admin
caller block mode is 'open' -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Caller
block mode is 'open' -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Load
callee preferences for uuid 'f2bdc2a5-b277-49c6-bc5f-2913cdc7e874' - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Load
dialplan IDs for domain 'maodi.sw1.domain.com' - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Fetched
dialplan IDs caller_out='35', callee_out='36' - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Dialog
set user, account to 'f2bdc2a5-b277-49c6-bc5f-2913cdc7e874/14' - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Checking
UPN '27835195154' and NPN '27835195154' against block in lists - R=
sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Admin
callee block mode is 'open' -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Callee
block mode is 'open' -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Dialog
set mark type to incoming -
R=sip:maodi1 at maodi.sw1.domain.comID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Local
user online, using alias as user - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
acc source-leg for uuid '0':
'0|27835195154|yyy.yy.yyy.yyy|27835195154|||<null>|||0|call|yyy.yy.yyy.yyy|1378712799.617176'
- R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
acc destination-leg for uuid 'f2bdc2a5-b277-49c6-bc5f-2913cdc7e874':
'0||Flexile|14|27110254990|f2bdc2a5-b277-49c6-bc5f-2913cdc7e874|maodi1|
maodi.sw1.domain.com|27110254990|xxx.xx.xxx.xxx' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Relaying
request, du='sip:lb at 127.0.0.1;lr;socket='sip:xxx.xx.xxx.xxx:5060'' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Usage of
mediaproxy forced by preference - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Use
mediaproxy for forward direction for IPv4/IPv4 -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Remove
existing ICE candidates (if any) for callee -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
P-Caller-UUID to '0' - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
P-Callee-UUID to 'f2bdc2a5-b277-49c6-bc5f-2913cdc7e874' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Sessions
Timers disabled for caller - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Sessions
Timers disabled for callee - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Applying
caller-out domain rewrite rules to first user-provided caller CLI using
dpid '35' - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
matching rewrite rules for '27835195154' found -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Applying
caller-out domain rewrite rules to first network-provided caller CLI using
dpid '35' - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
matching rewrite rules for '27835195154' found -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
userprovided caller domain - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Call from
peer, use callee domain 'maodi.sw1.domain.com' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Prepare
>From display-name setting - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
selector set, not setting CLI - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Prepare
>From username setting - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
caller_cli_userprov/caller_domain_userprov '27835195154 at maodi.sw1.domain.com'
for upn - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
>From to '<sip:27835195154 at maodi.sw1.domain.com>' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Prepare
PAI username setting - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
caller_cli_netprov/caller_domain_netprov '27835195154 at yyy.yy.yyy.yyy' for
npn - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
PAI to '<sip:27835195154 at yyy.yy.yyy.yyy>' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Prepare
PPI username setting - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
selector set, not setting CLI - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Prepare
Diversion setting - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
selector set, not setting CLI - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Applying
callee-out domain rewrite rules using dpid '36' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: No
matching rewrite rules for '27110254990' found -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Setting
P-Called-Party-ID '<sip:27110254990 at maodi.sw1.domain.com>' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Writing
sbc parameters  ;aleg_sst_enable=no;sst_enable=no -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Appending
P-D-URI 'sip:lb at 127.0.0.1;lr;socket='sip:xxx.xx.xxx.xxx:5060'' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Forcing
request via B2BUA 'sip:127.0.0.1:5080' - R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2322]: INFO: <script>: Request
leaving server, D-URI='sip:127.0.0.1:5080' -
R=sip:27110254990 at aaa.aa.aaa.aaa:5060
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2320]: INFO: <script>: NAT-Reply
- S=100 - Connecting M=INVITE IP=yyy.yy.yyy.yyy:5060 (127.0.0.1:5080)
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2318]: INFO: <script>: NAT-Reply
- S=200 - OK M=INVITE IP=yyy.yy.yyy.yyy:5060 (127.0.0.1:5080)
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2318]: INFO: <script>: Remove
existing ICE candidates (if any) for caller -
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2318]: INFO: <script>: Use
mediaproxy for backward direction -
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2316]: INFO: <script>: New
request - M=ACK R=sip:sems at 127.0.0.1:5080
F=sip:27835195154 at yyy.yy.yyy.yyyT=sip:27110254990 at xxx.xx.xxx.xxxIP=yyy.yy.yyy.yyy:5060
(
127.0.0.1:5060) ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2316]: INFO: <script>: Relaying
request, du='<null>' -
R=sip:sems at 127.0.0.1:5080ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2324]: INFO: <script>: New
request - M=BYE R=sip:sems at 127.0.0.1:5080
F=sip:27835195154 at yyy.yy.yyy.yyyT=sip:27110254990 at xxx.xx.xxx.xxxIP=yyy.yy.yyy.yyy:5060
(
127.0.0.1:5060) ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2324]: INFO: <script>: Stop
mediaproxy for all branches -
R=sip:sems at 127.0.0.1:5080ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2324]: INFO: <script>: Relaying
request, du='<null>' -
R=sip:sems at 127.0.0.1:5080ID=hs4_bhs6_b7012137605641968852-1378718951-12863
Sep  9 09:46:39 sipwise /usr/sbin/kamailio[2314]: INFO: <script>: NAT-Reply
- S=200 - OK M=BYE IP=yyy.yy.yyy.yyy:5060 (127.0.0.1:5080)
ID=hs4_bhs6_b7012137605641968852-1378718951-12863
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/mailman/private/spce-user_lists.sipwise.com/attachments/20130909/b0247a78/attachment.html>


More information about the Spce-user mailing list