WCS4: Very often Socket IO connection time out Errors

marcw

Member
Hello Max!
Please forgive me that I post a WCS4 question here but as long as I cannot switch to WCS5 I am still depending on my WCS4 and there is still - from the beginning on - a strange behaviour. Surely I should have try to fix it in the beginning and not in the ending time but I am in the personal debug mode since setting up WCS5 so that it was so near to have again now a deeper look into my old error which affected I think 1,000 or more users of my project every day. The connection is established and the callee can hear the caller (in my case the audio playbacks which are initialized by the users/callers) but the user cannot hear the callee. I increased now the verbose mode and found this for a failed test call from myself:
Code:
22:59:15,202 INFO   WCS4CallbackHandler - EventScanner-pool-11-thread-603 notifyAudioCodec pcma mpapp2@144.76.76.51
22:59:15,203 INFO               SipCall - EventScanner-pool-11-thread-603 Adding session to rtcMediaClient 9882b279-52fa-4022
22:59:15,203 INFO       AudioSdpFactory - EventScanner-pool-11-thread-603 proxySession: Session{secured=false, terminated=false, localPort=38362, rtcpMux=false, sdpState=sendrecv}
22:59:15,204 INFO                 Agent - EventScanner-pool-11-thread-603 Start ICE connectivity establishment
22:59:15,204 INFO                 Agent - EventScanner-pool-11-thread-603 Init checklist for stream audio
22:59:15,204 INFO  nectivityCheckClient - EventScanner-pool-11-thread-603 Start connectivity checks!
22:59:15,204 INFO   WCS4CallbackHandler - EventScanner-pool-11-thread-603 talk 9882b279-52fa-4022 mpapp2@144.76.76.51
22:59:15,205 INFO                     B - EventScanner-pool-11-thread-603 Config for method CallStatusEvent not found, using defaults
22:59:15,214 INFO  allResponseProcessor - EventScanner-pool-11-thread-603 scheduleSessionRefresh
22:59:15,214 INFO  allResponseProcessor - EventScanner-pool-11-thread-603 sessionExpiresHeader detected: expires=1800 refresher=uac
22:59:15,214 INFO               SipCall - EventScanner-pool-11-thread-603 scheduleSessionRefresh deltaTime=900000
22:59:15,214 INFO               SipCall - EventScanner-pool-11-thread-603 scheduleSessionRefresh: scheduledExecutionTime=Thu Jan 01 01:00:00 CET 1970
22:59:15,325 INFO  SipUserAgentListener - EventScanner-pool-11-thread-603 processTransactionTerminated: javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@26e20360]
22:59:15,459 INFO                 Agent - Stun4J Message Processor #2-1531342749804 set use-candidate true for pair /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,459 INFO                 Agent - Stun4J Message Processor #2-1531342749804 Receive check from /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)triggered a check
22:59:15,459 INFO                 Agent - Stun4J Message Processor #2-1531342749804 Add peer CandidatePair with new reflexive address to checkList
22:59:15,507 INFO                 Agent - Stun4J Message Processor #2-1531342749804 set use-candidate true for pair /144.76.76.51:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,507 INFO                 Agent - Stun4J Message Processor #2-1531342749804 Receive check from /144.76.76.51:38210/udp -> /176.199.236.217:60379/udp (audio.1)triggered a check
22:59:15,507 INFO                 Agent - Stun4J Message Processor #2-1531342749804 Add peer CandidatePair with new reflexive address to checkList
22:59:15,512 INFO  nectivityCheckClient - Stun4J Message Processor #2-1531342749804 Pair succeeded: /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,512 INFO  nectivityCheckClient - Stun4J Message Processor #2-1531342749804 Pair validated: /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,512 INFO  nectivityCheckClient - Stun4J Message Processor #2-1531342749804 IsControlling: false USE-CANDIDATE:false
22:59:15,512 INFO  nectivityCheckClient - Stun4J Message Processor #2-1531342749804 Nomination confirmed for pair: /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,513 INFO             CheckList - Stun4J Message Processor #2-1531342749804 Selected pair for stream audio.1: /144.76.76.27:38210/udp -> /176.199.236.217:60379/udp (audio.1)
22:59:15,513 INFO                 Agent - Stun4J Message Processor #2-1531342749804 CheckList of stream audio is COMPLETED
22:59:15,513 INFO                 Agent - Stun4J Message Processor #2-1531342749804 ICE state is COMPLETED
22:59:15,675 INFO      ProxyMediaClient - Old I/O datagram worker ([id: 0x63634ede, /144.76.76.51:38362]) notifyAudioTime TimePair{ts=160, time=1531342755675}
22:59:15,675 INFO      ProxyMediaClient - Old I/O datagram worker ([id: 0x63634ede, /144.76.76.51:38362]) notifyAudioTime TimePair{ts=160, time=1531342755675}
22:59:16,513 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:17,513 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:17,514 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:18,514 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:18,515 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 0
22:59:19,515 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:19,516 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:20,516 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:20,517 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:21,517 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:21,518 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:22,518 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:22,519 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
[...]
22:59:27,523 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:27,524 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:28,524 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:28,525 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:29,525 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:29,526 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:30,526 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:30,527 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:30,696 INFO      ProxyMediaClient - Old I/O datagram worker ([id: 0x63634ede, /144.76.76.51:38362]) notifyAudioTime TimePair{ts=120320, time=3740331570715}
22:59:31,527 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:31,528 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:32,528 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:32,529 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
22:59:33,529 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:33,530 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 0
22:59:34,530 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1000
22:59:34,531 ERROR TLSDatagramTransport - Stun4J Message Processor #2-1531342749804 Socket IO: Connect timed out; time - 1
Compared with the log of a successful call the first line which is different and which marks the problem is
Code:
22:59:15,325 INFO  SipUserAgentListener - EventScanner-pool-11-thread-603 processTransactionTerminated: javax.sip.TransactionTerminatedEvent[source=gov.nist.javax.sip.SipProviderImpl@26e20360]
Do you have any idea what the reason can be? I also recorded a pcap log if you want to have a look into it.
Again, I am sorry bothering with the old WCS4 and probably I can switch to WCS5 shortly but it is the first time now that I am able to find some useful log informations. Also this problem could occure also on the WCS5. Sure, the server software is different but some circumstanzes will not change: Same SIP provider and same data center for my server (same connectivity to the internet).

Best regards
Marc
 
Top