Rtmp stream audio time sync reset

pietjepuk · Nov 9, 2017

Hi,

We are using 'sip to rtmp' to call to a Twilio conference call and stream to a Wowza server. However, as soon as the conference call is started, wowza reports the following: "CupertinoPacketHandler.resetStream[......][11:0]: Timecodes jumped back in time.".

The timecode is reset to the time that the stream was started.

From client_logs/flashphoner.log:

Code:

15:37:45,360 INFO          AudioSession - pool-1-thread-5 forceRtmpAudioCodec null -1
15:37:45,366 INFO          MediaSession - pool-1-thread-5 Start rtp activity detecting for audio session 1335452b-fe47-4f02-91fc-0a170879ac40
15:37:45,366 INFO        RtpAudioPlayer - pool-1-thread-5 Rtp activity detecting started, port 31002
15:37:45,366 INFO          MediaSession - pool-1-thread-5 Initialized 1335452b-fe47-4f02-91fc-0a170879ac40
15:37:45,367 INFO          MediaSession - pool-1-thread-5 Create with video false
15:37:45,369 INFO      MediaTransponder - pool-1-thread-5 Created media transponder, feeding session 1335452b-fe47-4f02-91fc-0a170879ac40
15:37:45,369 INFO      MediaTransponder - pool-1-thread-5 Created rtmp transponder, rtmp url rtmp://....removed.....
15:37:45,374 INFO          MediaSession - pool-1-thread-5 Setting requested video resolution
15:37:45,375 INFO          MediaSession - pool-1-thread-5 Setting requested video quality 0
15:37:45,376 WARN          MediaSession - pool-1-thread-5 useAVGenerator Session description is unavailable!
15:37:45,384 INFO    AbstractRtpSession - pool-1-thread-5 Create Rtp Session - /....removed.....:31006 - /....removed.....:31007
15:37:45,385 INFO          MediaSession - pool-1-thread-5 Start rtp activity detecting for audio session l8dd0sn1ch0a5t5ecm267k6o0q
15:37:45,385 INFO        RtpAudioPlayer - pool-1-thread-5 Rtp activity detecting started, port 31006
15:37:45,385 INFO          MediaSession - pool-1-thread-5 Initialized l8dd0sn1ch0a5t5ecm267k6o0q
15:37:45,385 INFO      MediaTransponder - pool-1-thread-5 Session established
15:37:45,385 INFO  02-91fc-0a170879ac40 - AudioDistributor-mpeg4-generic-1335452b-fe47-4f02-91fc-0a170879ac40 Starting with queue size 0
15:37:45,393 ERROR         MediaSession - pool-1-thread-5
java.lang.NullPointerException
    at com.flashphoner.media.H.C$1.A(Unknown Source)
    at com.flashphoner.media.D.a(Unknown Source)
    at com.flashphoner.media.D.K(Unknown Source)
    at com.flashphoner.media.D.R(Unknown Source)
    at com.flashphoner.media.D.N(Unknown Source)
    at com.flashphoner.media.D.A(Unknown Source)
    at com.flashphoner.media.H.C.A(Unknown Source)
    at com.flashphoner.media.H.C.D(Unknown Source)
    at com.flashphoner.media.H.C.A(Unknown Source)
    at com.flashphoner.media.H.D.A(Unknown Source)
    at com.flashphoner.media.D.a(Unknown Source)
    at com.flashphoner.media.D.K(Unknown Source)
    at com.flashphoner.media.D.R(Unknown Source)
    at com.flashphoner.media.D.r(Unknown Source)
    at com.flashphoner.media.D.A(Unknown Source)
    at com.flashphoner.sip.C.K.C(Unknown Source)
    at com.flashphoner.sip.C.A.c(Unknown Source)
    at com.flashphoner.sip.C.A.C(Unknown Source)
    at com.flashphoner.sip.C.A.f(Unknown Source)
    at com.flashphoner.sip.C.G.processResponse(Unknown Source)
    at com.flashphoner.sip.D.A(Unknown Source)
    at com.flashphoner.sip.D.access$700(Unknown Source)
    at com.flashphoner.sip.D$_A.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
15:37:45,394 INFO      MediaTransponder - pool-1-thread-5 Init rtmp writer
15:37:46,334 INFO  leParticipantSession - RTP-pool-22-thread-1 Disable ignore packets from unknown ssrc
15:37:46,334 INFO  leParticipantSession - RTP-pool-22-thread-1 First packet received from remote source, updated SSRC to 905897566.
15:37:47,333 WARN  ediaSessionSyncPoint - RTP-pool-22-thread-1 Audio sync not available, use first packet time!

Code:

15:38:08,262 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1335452b-fe47-4f02-91fc-0a170879ac40 Not enough data in audio buffer, current data size 1821
15:38:08,322 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1335452b-fe47-4f02-91fc-0a170879ac40 Synchronization time drop, requested 1510241888321 current 1510241874995

Could the exception have anything to do with it? Also, the last log line "Audio sync not available, use first packet time!" might be of interest. I see a bunch of messages saying there is not enough data in audio buffer and synchronization time drop, although this does not match with the exact moment that timecodes are reset. But might indicate some underlying issue.

Please let me know if you need more information. I'd need a support email address that i can send the complete log files to, because this forum is public.

Thanks in advance for your help.

Max · Nov 10, 2017

Hello
What is your server version?
For latest server versions, try to add the following setting to WCS_HOME/conf/flashphoner.properties

Code:

rtp_force_synchronization =true

Restart WCS server to apply changes:

Code:

service webcallserver restart

pietjepuk · Nov 10, 2017

I updated to version: 5.0.2552 and added the line rtp_force_synchronization =true to our properties file.

The issue still occurs. It did remove the line ""Audio sync not available, use first packet time!"". The log is now as follows:

Code:

08:41:11,886 INFO          AudioSession - pool-21-thread-5 forceRtmpAudioCodec null -1
08:41:11,910 INFO          MediaSession - pool-21-thread-5 Start rtp activity detecting for audio session 1a78bbcb-816c-469f-b7c5-3ae754a08638
08:41:11,910 INFO        RtpAudioPlayer - pool-21-thread-5 Rtp activity detecting started, port 31002
08:41:11,912 INFO          MediaSession - pool-21-thread-5 Initialized 1a78bbcb-816c-469f-b7c5-3ae754a08638
08:41:11,913 INFO          MediaSession - pool-21-thread-5 Create with video false
08:41:11,914 INFO      MediaTransponder - pool-21-thread-5 Created media transponder, feeding session 1a78bbcb-816c-469f-b7c5-3ae754a08638
08:41:11,915 INFO      MediaTransponder - pool-21-thread-5 Created rtmp transponder, rtmp url .....our rtmp url.....
08:41:11,945 INFO          MediaSession - pool-21-thread-5 Setting requested video resolution
08:41:11,945 INFO          MediaSession - pool-21-thread-5 Setting requested video quality 0
08:41:11,951 WARN          MediaSession - pool-21-thread-5 useAVGenerator Session description is unavailable!
08:41:11,966 INFO    AbstractRtpSession - pool-21-thread-5 Create Rtp Session - /.....ip address.... - /.....ip address....
08:41:11,971 INFO          MediaSession - pool-21-thread-5 Start rtp activity detecting for audio session bsivr0uvdfn7csi5ccc823gmg7
08:41:11,973 INFO        RtpAudioPlayer - pool-21-thread-5 Rtp activity detecting started, port 31006
08:41:11,973 INFO          MediaSession - pool-21-thread-5 Initialized bsivr0uvdfn7csi5ccc823gmg7
08:41:11,973 INFO      MediaTransponder - pool-21-thread-5 Session established
08:41:11,976 ERROR         MediaSession - pool-21-thread-5
java.lang.NullPointerException
    at com.flashphoner.media.H.C$1.onSessionEstablished(Unknown Source)
    at com.flashphoner.media.D.b(Unknown Source)
    at com.flashphoner.media.D.K(Unknown Source)
    at com.flashphoner.media.D.R(Unknown Source)
    at com.flashphoner.media.D.N(Unknown Source)
    at com.flashphoner.media.D.A(Unknown Source)
    at com.flashphoner.media.H.C.A(Unknown Source)
    at com.flashphoner.media.H.C.D(Unknown Source)
    at com.flashphoner.media.H.C.A(Unknown Source)
    at com.flashphoner.media.H.D.A(Unknown Source)
    at com.flashphoner.media.D.b(Unknown Source)
    at com.flashphoner.media.D.K(Unknown Source)
    at com.flashphoner.media.D.R(Unknown Source)
    at com.flashphoner.media.D.r(Unknown Source)
    at com.flashphoner.media.D.A(Unknown Source)
    at com.flashphoner.sip.D.K.A(Unknown Source)
    at com.flashphoner.sip.D.A.e(Unknown Source)
    at com.flashphoner.sip.D.A.C(Unknown Source)
    at com.flashphoner.sip.D.A.h(Unknown Source)
    at com.flashphoner.sip.D.G.processResponse(Unknown Source)
    at com.flashphoner.sip.D.A(Unknown Source)
    at com.flashphoner.sip.D.access$700(Unknown Source)
    at com.flashphoner.sip.D$_A.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
08:41:11,980 INFO      MediaTransponder - pool-21-thread-5 Init rtmp writer
08:41:12,008 INFO  9f-b7c5-3ae754a08638 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Starting with queue size 0
08:41:12,859 INFO  leParticipantSession - RTP-pool-23-thread-1 Disable ignore packets from unknown ssrc
08:41:12,859 INFO  leParticipantSession - RTP-pool-23-thread-1 First packet received from remote source, updated SSRC to 1619749514.
08:41:12,886 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1765
08:41:13,020 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1825
08:41:13,159 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1885
08:41:13,300 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1945
08:41:13,439 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 2005
08:41:13,599 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1781
08:41:13,739 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1841
08:41:13,879 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Not enough data in audio buffer, current data size 1901
08:41:14,020 WARN  -mpeg4-generic/44100 - AudioDistributor-mpeg4-generic-1a78bbcb-816c-469f-b7c5-3ae754a08638 Synchronization time drop, requested 1510303272961 current 1510303273974

Max · Nov 10, 2017

Hello,

The exception is not related to the issue.
Please let know if the issue can be reproduced
- if call not to conference but e.g. to a Twilio SIP domain (Programmable Voice), or
- with this RTMP server: rtmp://rtmp.flashphoner.com:1935/live
Server logs can be sent to logs@flashphoner.com. Please send network traffic dump as well.

pietjepuk · Nov 10, 2017

Hi,

I sent an email with the log files.

I performed two tests:

siptortmp twilio voice app
Call using a twilio sip domain to a twiml app that plays music in a loop and stream to the flasphoner rtmp server.

We do not experience the issue of audio timecodes resetting. But there are a lot of warning concerning the audio buffer. Also, the included vlc media player debug log shows there is some drift.

siptortmp twilio conference
Call using a twilio sip domain to a twiml app that puts the caller in a conference call. Streams to the flashphoner rtmp server.

This is where the issue occurs. At first, the stream is ok. This is as long as twilio conference isn’t started, because there is only one participant. As soon as we join the conference call with another client, the conference call is started and the timecode reset occurs. This happens around 14:59:20 UTC. You can also see this happening in the vlc media player debug log. It shows some errors, starts buffering, reporting ‘buffer too late’ and stops playback.

The tcpdump.pcap files are a network dump of the ports 1935, 30000, 31000, 31001 and 32000.

Please let me know if you need more information.

Thanks in advance for your help.

Max · Nov 13, 2017

Hello,

Please try adding the following settings to WCS_HOME/conf/flashphoner.properties

Code:

rtp_audio_max_consecutive_sn_errors=1
rtp_audio_reset_buffer_on_sn_error=true

Restart the server to apply the changes.

pietjepuk · Nov 13, 2017

Hi,

No luck i'm afraid. The issue still occurs on our wowza server. I tried the new configuration both with and without the earlier proposed rtp_force_synchronization setting.

Vlc media player playback failed even before the conference was started. The change caused more synchronization errors and a vlc playback error we didn't have before:

Code:

core warning: clock gap, unexpected stream discontinuity
core warning: feeding synchro with a new reference point trying to recover from clock gap

I sent the logs to logs@flashphoner.com.

Thanks

Max · Nov 14, 2017

Hello,

For Twilio conference (without the settings suggested yesterday), please send network traffic dump with RTP received from Twilio not filtered out.
Also, could we use your Twilio conference for reproducing the issue?

pietjepuk · Nov 14, 2017

Hi,

I emailed log files and a dump containing the rtp packets. The issue occurs around 13:05:35 UTC.

You can also find steps to reproduce the issue in the email.

Max · Nov 15, 2017

Hello,

As can be seen from the dump, RTMP timestamp is reset after RTP timestamp reset, which occurs when a conference is started.
We recommend to contact Twilio for a comment as to the grounds of RTP timestamp reset in relevance with specification.

pietjepuk · Nov 16, 2017

Hi,

Can you please contact Twilio about this issue? Since you have a better understanding of how you are capturing this audio and interpreting it. We were under the impression that Twilio was one of the services you supported with SIP to RTMP.

Marcel Brouns · Nov 16, 2017

Hi guys... pietjepuk above is my collegue. Please advice on how to proceed on a full refund.
We bought 2 licenses, which are quite expensive, for a feature that you list on your website as working. As it seems that it is in fact not working, and i get the impression that you won't or can't fix it, we have no need for you software. Best regards.

Max · Nov 16, 2017

Hello
This is a tech forum. Please contact sales@flashphoner.com if you have any payment or licensing related questions.

Max · Nov 16, 2017

Can you please contact Twilio about this issue? Since you have a better understanding of how you are capturing this audio and interpreting it. We were under the impression that Twilio was one of the services you supported with SIP to RTMP.

Well we will contact Twiilio support. I will inform you through this thread once we have any news.

Max · Nov 17, 2017

aac_encoder_sync_drop_threshold config property has been added for processing timestamp reset in source RTP stream in case of audio-only SIP as RTMP with AAC codec. The property can be set in WCS_HOME/conf/flashphoner.properties.

In case of the Twilio conference, WCS server should be updated to the latest version and this setting should be added to flashphoner.properties

Code:

aac_encoder_sync_drop_threshold=1000000

This setting should be removed from the flashphoner.properties

Code:

rtp_force_synchronization=true

With Twilio conference, timestamp reset in RTMP stream was not reproducible in our environment. However, there was a different issue - RTMP timestamp jump - which resulted in wrong duration of the stream record on Wowza. It has been verified that issue - RTMP timestamp jump - does not occur with server v. 2564 when aac_encoder_sync_drop_threshold=1000000.

pietjepuk · Nov 20, 2017

Hi,

Thanks, that seems to fix it. We will do some more testing. But looking good.

pietjepuk · Nov 22, 2017

Issue still occurs if we start the conference after half an hour or so of streaming. It didn't happen when we started within a few minutes of starting the stream.

WARN - server - MPEGDashWriterHandler.endChunk[live/WEBCALLSERVER01/7d6ffa42-b94d-4df0-8acd-97c9e7fa2e76]: Stream start time calculation is off by 2121165ms from original value. Changing stream start date from "Tue Nov 21 15:27:58 UTC 2017" to "Tue Nov 21 14:52:37 UTC 2017"

What does this threshhold in the config mean (aac_encoder_sync_drop_threshold=1000000)? Does it only fix the issue if it happens before x amount of time has passed?

To reproduce, follow steps i sent you earlier, but wait 40minutes before joining the conference with a second client (thus starting it).

Thanks

Max · Nov 22, 2017

Hello

Does it only fix the issue if it happens before x amount of time has passed?

Yes. This is a workaround suppressing timestamp gaps from Twilio. Try to set greater value to cover cases with later joining.
Example 30 days = 30*24*3600*1000 = 2592000000

Code:

aac_encoder_sync_drop_threshold=2592000000

Or just an arbitrary round long value:

Code:

aac_encoder_sync_drop_threshold=1000000000

Rtmp stream audio time sync reset

pietjepuk

New Member

Attachments

Max

Administrator

pietjepuk

New Member

Attachments

Max

Administrator

pietjepuk

New Member

Max

Administrator

pietjepuk

New Member

Max

Administrator

pietjepuk

New Member

Max

Administrator

Attachments

pietjepuk

New Member

Marcel Brouns

New Member

Max

Administrator

Max

Administrator

Max

Administrator

pietjepuk

New Member

pietjepuk

New Member

Max

Administrator