Trial release hangup timer

Andreti

New Member
Hello, my company is evaluating the trial version. We are testing the GW to SIP calls, but as We can see , all the calls are disconnected more or less after 50 seconds. Is this an issue or it's just a flashphner timer for tge trial version?
Thanks in advance.
 

Max

Administrator
Staff member
Looks like an issue. It does not have a timer.
You can analyse the issue in logs:
Code:
/usr/local/FlashphonerWebCallServer/logs/server_logs
or
Code:
tcpdump udp -s 2048 -w log.pcap
to see who terminates the SIP session.
 

Andreti

New Member
Thanks a lot for your quick answer.
I've just reproduced the issue but with your indications the traces are empty:

tcpdump udp -s 2048 -w ./loghanguptimer.pcap
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 2048 bytes
^C21163 packets captured
21163 packets received by filter
0 packets dropped by kernel
root@bale:/home/imagine800#

And the log as well:
/usr/local/FlashphonerWebCallServer/logs/server_logs# tail -f flashphoner.log
01:22:24,672 WARN WSServerHandler - WS-pool-6-thread-7 Close channel because: org.jboss.netty.handler.codec.http.websocketx.WebSocketHandshakeException 'not a WebSocket handshake request: missing upgrade'

I'll try to explain my scenario in more detail in the attached file. I'll send you in a private message the pcap message that we have in port 5060 but basically what we see is that

BYE sip:555196934983071606@85.x.x.x:5060 SIP/2.0

Via: SIP/2.0/UDP 85.x.x.x:30000;branch=z9hG4bK18d18f7ce40019320bb70f8de6e547f6

CSeq: 2 BYE

From: "9188833ff" <sip:9188833ff@xxxxx.axxxa.es>;tag=c4f2a89a

To: <sip:5xxxxxxxxx071606@xxxxx.axxxa.es>;tag=as34a7adf7

Call-ID: A423F837-929D-4F12-BF2A-2D03BDDBEAAC

Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,SUBSCRIBE,NOTIFY,INFO,PUBLISH

Supported: replaces,timer

Session-Expires: 1800;refresher=uac

Max-Forwards: 70

User-Agent: WebRTC

Content-Length: 0
 

Attachments

Andreti

New Member
By the wat, I'm not sure if I can send private messages wuth pcap files, Is it possible?

Thanks again?.
 

Max

Administrator
Staff member
We have analyzed your pcap file.
Form the pcap file we can see that WCS sends BYE request to your Asterisk server.
Please send server log:
%WCS_HOME%/logs/server_logs/flashphoner.log
Please note it is rotated hourly. You can find this logfile if you know date and time of your previous test.
 

Andreti

New Member
Thabks again.
I've sent the log in a private mail.
Basically the logs ends with this:

11:41:38,801 INFO WCS4CallbackHandler - Timer-613 finish SipCall{id='6D35EB50-6EEB-4F8A-BA67-8A9AE3914374', cost='', callee='5xxxxxxxxx6', calleeVisibleName='<sip:xxxxxxx@xxxx>', caller='918883er', callerVisibleName='918883er', isVideoCall=true, incoming=false, terminated=true, state=FINISH, lastResponseStatusCode=200} 918883er@xxxxx
11:41:38,802 INFO Streams - Timer-613 destroyPublication name IN_918883er_6D35EB50-6EEB-4F8A-BA67-8A9AE3914374
11:41:38,802 INFO ManagerApiConnection - Timer-613 Config for method CallStatusEvent not found, using defaults
11:41:38,832 INFO SipCall - Timer-613 cancelScheduleSessionRefresh
11:41:38,834 INFO SipUserAgent - Timer-613 Shutdown instance. Count: 1 this: SIP UA: login: 918883er assignedPort: 30001 listeningPort: 30001
 

Max

Administrator
Staff member
It was in spam. Please do not insert logfile in the email body next time.
 

Max

Administrator
Staff member
The root cause of issue is your websocket connection is closed by your browser in 40-50 seconds.
Try to open a page like Two Way Streaming and do connect then wait for 1 minute.
If it is disconnected, it looks like our issue.
If it is not disconnected, it seems your server configuration issue.
Try to
1. Edit file
Code:
server.properties
and set
Code:
keep_alive.algorithm=INTERNAL
2. Edit file
Code:
log4j.properties
and add this second line:
Code:
log4j.logger.WSClients=DEBUG
These settings require WCS restart.
If it is reproduced with your configuration, please send logs again.
 

Andreti

New Member
Hi,
sorry for the mail qith log in the body. I've just sent a new log to
logs@flashphoner.com

Actually, we are using PhoneMin for iOS. It's nothing to do with the two way streams, since it's only audio to asterisk PSTN.
 

Andreti

New Member
Additional info... We have exactly the same behaviour usin android phonemin:

Client didn't pushed logs to server, try to enable push_log at client side.
[-- END CLIENT LOG ----]
18:20:46,020 INFO WCS4Handler - WSClientsKeepaliveThread-65 Report client-918883eer-2017.02.20.18.20.46-1487611246020.report is submitted
18:20:46,022 INFO ManagerApiConnection - WSClientsKeepaliveThread-65 Config for method ConnectionStatusEvent not found, using defaults
18:20:46,067 DEBUG WSClients - WSClientsKeepaliveThread-65 Current channels: Before remove
Channel: [id: 0x37232f34, /xx.xx.xx.108:38795 :> /xx.xx.xx.12:8080]; isOpen: false; Client 1: null

18:20:46,067 DEBUG WSClients - WSClientsKeepaliveThread-65 Remove client for channel [id: 0x37232f34, /xx.xx.xx.108:38795 :> /xx.xx.xx.12:8080]
18:20:46,067 DEBUG WSClients - WSClientsKeepaliveThread-65 Remove and close client: WSClient{channel=[id: 0x37232f34, /xx.xx.xx.108:38795 :> /xx.xx.xx.12:8080], handler=com.flashphoner.server.client.handler.DelegateHandler@2cc68945, closed=false, pageUrl='null', countUnansweredPing=1}
18:20:51,023 DEBUG sipMessages - Timer-652

--------------------> BYE sip:5555555983071606@xx.xx.xx.12:5060 SIP/2.0
from: /xx.xx.xx.12:30000
to: /xx.xx.xx.12:5060
time: 1487611251022
timeStamp:
isSender: true
transactionId: z9hg4bkd6aa61cadfcd686425454e227ddd7c6c
callId: 74e46111-0794-4e06-a49a-43f51dd8a500

BYE sip:5555555983071606@xx.xx.xx.12:5060 SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.12:30000;branch=z9hG4bKd6aa61cadfcd686425454e227ddd7c6c
CSeq: 2 BYE
From: "918883eer" <sip:918883eer@xx.xx.xx.es>;tag=65da497f
To: <sip:5555555983071606@xx.xx.xx.es>;tag=as3597bcfb
Call-ID: 74e46111-0794-4e06-a49a-43f51dd8a500
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,SUBSCRIBE,NOTIFY,INFO,PUBLISH
Supported: replaces,timer
Session-Expires: 1800;refresher=uac
Max-Forwards: 70
User-Agent: WebRTC
Content-Length: 0


18:20:51,023 INFO SipCallProcessor - Timer-652 terminate: sipCall.id=74e46111-0794-4e06-a49a-43f51dd8a500
18:20:51,025 INFO SipCallProcessor - Timer-652 Stop rtc media session id RTC-74e46111-0794-4e06-a49a-43f51dd8a500, sipCallId 74e46111-0794-4e06-a49a-43f51dd8a500
18:20:51,025 INFO Agent - Timer-652 Free ICE agent
18:20:51,028 INFO Agent - StunKeepAliveThread-RTC-74e46111-0794-4e06-a49a-43f51dd8a500 KeepAliveThread ends
18:20:51,028 INFO Agent - Timer-652 remove streams
18:20:51,032 INFO Agent - Timer-652 remove stream audio
18:20:51,033 DEBUG sipMessages - UDPMessageChannelThread-30000-6518

<-------------------- SIP/2.0 200 OK
from: /xx.xx.xx.12:5060
to: /xx.xx.xx.12:30000
time: 1487611251025
timeStamp:
isSender: false
transactionId: z9hg4bkd6aa61cadfcd686425454e227ddd7c6c
callId: 74e46111-0794-4e06-a49a-43f51dd8a500

SIP/2.0 200 OK
Via: SIP/2.0/UDP xx.xx.xx.12:30000;branch=z9hG4bKd6aa61cadfcd686425454e227ddd7c6c;received=xx.xx.xx.12;rport=30000
From: "918883eer" <sip:918883eer@xx.xx.xx.es>;tag=65da497f
To: <sip:5555555983071606@xx.xx.xx.es>;tag=as3597bcfb
Call-ID: 74e46111-0794-4e06-a49a-43f51dd8a500
CSeq: 2 BYE
Server: Asterisk PBX 11.7.0~dfsg-1ubuntu1
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,SUBSCRIBE,NOTIFY,INFO,PUBLISH
Supported: replaces,timer
Content-Length: 0


18:20:51,036 INFO Agent - Timer-652 ICE agent freed
18:20:51,042 INFO WCS4CallbackHandler - Timer-652 finish SipCall{id='74e46111-0794-4e06-a49a-43f51dd8a500', cost='', callee='5555555983071606', calleeVisibleName='<sip:5555555983071606@xx.xx.xx.es>', caller='918883eer', callerVisibleName='918883eer', isVideoCall=false, incoming=false, terminated=true, state=FINISH, lastResponseStatusCode=200} 918883eer@xx.xx.xx.es
18:20:51,046 INFO Streams - Timer-652 destroyPublication name IN_918883eer_74e46111-0794-4e06-a49a-43f51dd8a500
18:20:51,046 INFO ManagerApiConnection - Timer-652 Config for method CallStatusEvent not found, using defaults
18:20:51,074 INFO SipCall - Timer-652 cancelScheduleSessionRefresh
18:20:51,074 INFO SipUserAgent - Timer-652 Shutdown instance. Count: 0 this: SIP UA: login: 918883eer assignedPort: 30000 listeningPort: 30000
 

Max

Administrator
Staff member
Thanks for the report
Let me resume the issue report:
- Android or iOS, Phone Min Video
- Call is dropped in 1 minute
- WCS detects disconnect and sends BYE request to Asterisk server
As I see from logs, the mobile app closes its connection by keep alive timeout because network is overload by video traffic between the mobile app and WCS.
I will pass this issue to our dev team for investigation. I will able to inform you through this thread once we have any news.
 

Andreti

New Member
Thanks a lot Max. Just one comment, in all the cases it was voice call, no video.
I've just tried as well with android web explorer and the same problem.

BR
 

Max

Administrator
Staff member
Unfortunately we can't reproduce this issue in our environment.
Our env
OpenSIPs
Android SDK latest
iOS SDK latest
WCS server build 2099

Please provide your versions of
- WCS server
- Android SDK (app)
- Used devices

If your Asterisk is a publicly available, please provide two extensions for testing. We will conduct the same test over your Asterisk server.
If your Asterisk is public or if you have a public SIP provider accounts, you can test your case over our demo server: https://wcs5-eu.flashphoner.com/demo2/phone
Note, you can download latest build of the Phone Android app from google play or apk file from our website: https://flashphoner.com/wcs-android-sdk
 

Andreti

New Member
>>> New version available: 5.0.2099
>>> Your version: 5.0.2080

We are going to update and retest the scenario. I'll keep you informed.
Thanks.
 
Top