can't transfer data when not in a lan

[377517827]

version: commit 4e13ff8

issue: when master and viewer connect the same network, transfer video data ok. But when master and viewer not in the same network, viewer can't get any video data.

master log:master.txt

viewer log:viewer.txt

[disa6302]

@377517827 ,

It looks like the viewer is encountering SSL_write failed with error:00000002:lib(0):func(0):system lib error. This indicates the SSL_ERROR_WANT_READ which happens when the socket is in non blocking mode and SSL needs data from the peer. There is an active PR fixing this (#322).

[ycyang1229]

@377517827 This commit(4d76c92) may be helpful, since you can not receive the stun packets under wp2-enterprise network when you want to use turn.

[ycyang1229]

@chehefen Would you mind giving us more detail about this commit(4d76c92)? For example, any logs or phenomena indicates the abnormal scenario, and this commit can fix it.

[ycyang1229]

@chehefen Could you check this log?

2020-04-13 07:06:48 VERBOSE lwsHttpCallbackRoutine(): HTTPS callback with reason 71
2020-04-13 07:06:48 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 71
2020-04-13 07:06:48 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 07:06:48 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 07:06:48 DEBUG iceAgentGatherCandidateTimerCallback(): Candidate gathering completed.
2020-04-13 07:06:48 DEBUG onIceCandidateHandler(): ice candidate gathering finished
2020-04-13 07:06:48 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:06:48 DEBUG turnConnectionHandleStun(): Allocation life time is 600 seconds
2020-04-13 07:06:48 DEBUG turnConnectionHandleStun(): TURN Allocation succeeded. Allocation expiration epoch 158676220879733
2020-04-13 07:06:49 DEBUG turnConnectionHandleStun(): Allocation life time is 599 seconds
2020-04-13 07:06:49 DEBUG turnConnectionHandleStun(): TURN Allocation succeeded. Allocation expiration epoch 158676220806146
2020-04-13 07:06:49 DEBUG turnConnectionHandleStun(): create permission succeeded for peer 13.115.17.35
2020-04-13 07:06:49 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:49 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 8
2020-04-13 07:06:49 DEBUG lwsWssCallbackRoutine(): Client receive
2020-04-13 07:06:49 WARN receiveLwsMessage(): Signaling received an empty message
2020-04-13 07:06:49 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 07:06:49 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 07:06:49 DEBUG turnConnectionHandleStun(): create permission succeeded for peer 103.29.142.216
2020-04-13 07:06:49 DEBUG turnConnectionHandleStun(): Channel bind succeeded with peer 13.115.17.35, port: 58309, channel number 16387
2020-04-13 07:06:50 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:50 DEBUG turnConnectionStepState(): TurnConnection state changed from TURN_STATE_CREATE_PERMISSION to TURN_STATE_BIND_CHANNEL
2020-04-13 07:06:50 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:50 DEBUG turnConnectionHandleStun(): Channel bind succeeded with peer 103.29.142.216, port: 50552, channel number 16386
2020-04-13 07:06:50 WARN iceAgentSendPacket(): No valid ice candidate pair available to send data
2020-04-13 07:06:51 ERROR turnConnectionHandleChannelDataTcpMode(): operation returned status code: 0x5a000024
2020-04-13 07:06:51 ERROR turnConnectionHandleChannelData(): operation returned status code: 0x5a000024
2020-04-13 07:06:51 ERROR turnConnectionIncomingDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:51 ERROR incomingRelayedDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:52 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:52 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:52 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:53 ERROR turnConnectionHandleChannelDataTcpMode(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR turnConnectionHandleChannelData(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR turnConnectionIncomingDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR incomingRelayedDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR turnConnectionHandleChannelDataTcpMode(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR turnConnectionHandleChannelData(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR turnConnectionIncomingDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 ERROR incomingRelayedDataHandler(): operation returned status code: 0x5a000024
2020-04-13 07:06:53 DEBUG turnConnectionStepState(): TurnConnection state changed from TURN_STATE_BIND_CHANNEL to TURN_STATE_READY
2020-04-13 07:06:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:53 WARN turnConnectionHandleStunError(): Received STUN error response. Error type: 0x00, Error Code: 403. Error detail: Forbidden IP�".
2020-04-13 07:06:53 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:06:53 DEBUG stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000040
2020-04-13 07:06:53 ERROR executeFailedIceAgentState(): IceAgent failed with 0x5a00000d
2020-04-13 07:06:53 DEBUG stepIceAgentStateMachine(): Ice agent state changed from ICE_AGENT_STATE_CHECK_CONNECTION to ICE_AGENT_STATE_FAILED.
2020-04-13 07:06:53 INFO onConnectionStateChange(): New connection state 5
2020-04-13 07:06:53 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:06:53 DEBUG freeSampleStreamingSession(): Freeing streaming session with peer id: ConsumerViewer
2020-04-13 07:06:54 DEBUG turnConnectionStepState(): TurnConnection state changed from TURN_STATE_READY to TURN_STATE_CLEAN_UP
2020-04-13 07:06:56 DEBUG turnConnectionShutdown(): Failed to free turn allocation within timeout of 3000 milliseconds
2020-04-13 07:06:58 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 07:06:58 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 07:06:59 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 9
2020-04-13 07:07:01 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:07:06 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:07:09 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 07:07:09 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 07:07:09 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 9
2020-04-13 07:07:11 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:07:16 INFO signalingClientGetCurrentState(): Signaling Client Get Current State
2020-04-13 07:07:19 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10

log_master-with-new-commit.txt
log_viewer-with-new-commit.txt

[ycyang1229]

@chehefen another strange behavior.
2020-04-13 08:08:14 VERBOSE lwsHttpCallbackRoutine(): HTTPS callback with reason 71
2020-04-13 08:08:14 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 71
2020-04-13 08:08:14 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 08:08:14 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 08:08:14 DEBUG stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
2020-04-13 08:08:14 DEBUG iceAgentCheckConnectionStateSetup(): ice candidate pair count 0
2020-04-13 08:08:14 DEBUG stepIceAgentStateMachine(): Ice agent state changed from ICE_AGENT_STATE_NONE to ICE_AGENT_STATE_CHECK_CONNECTION.
2020-04-13 08:08:14 INFO onConnectionStateChange(): New connection state 2
2020-04-13 08:08:14 DEBUG turnConnectionStepState(): TurnConnection state changed from TURN_STATE_NEW to TURN_STATE_CHECK_SOCKET_CONNECTION
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 8
2020-04-13 08:08:14 DEBUG lwsWssCallbackRoutine(): Client receive
2020-04-13 08:08:14 WARN receiveLwsMessage(): Signaling received an empty message
2020-04-13 08:08:14 VERBOSE lwsWssCallbackRoutine(): WSS callback with reason 10
2020-04-13 08:08:14 DEBUG lwsWssCallbackRoutine(): Client is writable
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:14 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN iceAgentSendPacket(): No valid ice candidate pair available to send data
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:15 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:16 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:16 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:16 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:16 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress
2020-04-13 08:08:16 WARN socketConnectionIsConnected(): socket connection check failed with errno Operation already in progress

log_master_turn.txt

[ycyang1229]

These logs came after updating to the newest commit.

[chehefen]

It seems that TCP connection cannot be established. Can you check your firewall setting?

[LiuAriel]

Yes, the same problem is currently encountered, a little Low Turn Success Rate in Devices

1. STATUS_INVALID_STORAGE_INFO_VERSION == 0x5a00000d, STATUS_ICE_FAILED_TO_NOMINATE_CANDIDATE_PAIR = 0x5a000013, through packet capture, the kvs server stun / turn is modified based on coturn, theoretically detecting that the parameter verification in these attributes should not fail, in fact often fails, region: ap-east- 1. It's hard to understand.
2. The four-way handshake is successful, whether it is a request packet: bindrequest, or a reply packet: bindresponse, they are all sent repeatedly, because the transaction ID and other information are the same, and there is no waiting for a question and answer or event timer timeout mechanism. Retransmissions continue to cause pressure on the network bandwidth, and there is almost no difference between the time spent in the trickleICE mode and the fullICE hole punching process, which does not reflect the advantage of the time-consuming trickleICE mode.

[chehefen]

@juno52wendy, for issue 1, can you tell us what are you using as viewer? if it is the js sample, can you tell us which browser you are using? Also can you show us the log when it fails?
For issue 2. you can try to adjust the connection check interval here: https://github.com/awslabs/amazon-kinesis-video-streams-webrtc-sdk-c/blob/master/src/source/Ice/IceAgent.h#L24. However, each binding request packet is about 62 byte, and currently connection check interval is 50ms, so the bitrate would be 62 * 20 packets/sec = 1240 bytes / sec. It shouldn't have caused much pressure on the network bandwidth.

[LiuAriel]

@chehefen

1. Use the js viewer to view, the browser is Chrome 80.0.3987.163, the log is the same as the one posted by issuse;
2. I may have described it briefly, although each packet does not have many bytes, but each message packet is not processed after waiting for timeout processing or response, and it directly sends multiple packets multiple times to prevent the problem of packet loss. But it's very rough, and it's not a good code logic processing method;

[ycyang1229]

Summarize the result of experiments from the beginning.
#1: two devices connect the same wifi access point(wpa2-personal). Success.
success_viewer_log.txt
success_master_log.txt

#2: one device connects to one wifi access point(wpa2-personal), and another device connects to another wifi acccess point(wpa2-enterprise). Failed.
fail_master_log.txt

#3: updated codebase to the commit(4d76c92). one device connects to one wifi access point(wpa2-personal), and another device connects to another wifi acccess point(wpa2-enterprise). Failed.
log_master-with-new-commit.txt
log_viewer-with-new-commit.txt

#4: change the protocol of turn from tcp to udp. one device connects to one wifi access point(wpa2-personal), and another device connects to another wifi acccess point(wpa2-enterprise). Failed.
UDP.zip

#5: using two web test pages on different laptops and connect to the same wifi access point(wpa2-enterprise). Success
js_good.pcapng.zip

#6: two devices connect to the same wifi access point(wpa2-enterprise) after exp#5. Failed
c_cleanup.zip

Confirmed with IT guy, and no block operation is used. Based on the result of #5, it can work when using web test pages, but c sdk can not work well.

[ycyang1229]

The process of turn seems not to be normal. Before updating the specific commit(4d76c92) , logs usually show socket in use, sendto error.. etc. After updating the specific commit, the error of logs became less.

[LiuAriel]

The process of turn seems not to be normal. Before updating the specific commit(4d76c92) , logs usually show socket in use, sendto error.. etc. After updating the specific commit, the error of logs became less.

At present, it is true that c sdk is immature and there is still a certain distance from productization. When docking with its own product echoshow, it not only has high requirements for network delay, but also has a very low success rate. Especially for the turn server, the analysis of Allocate request, create permission, channelbind, channeldata, send indication is often unsuccessful. The turn server of the package capture kvs is also based on the modification of the open source coturn server source code. Perfect, still waiting for more mature and docking products.

[chehefen]

Hi @377517827, your issue should be fixed as of d273359. Can you try it out? Thanks.