FMS 3.5 says 'Bad network data': error in handling RTMP extended timestamps / chunkSize?

Report · Jun 03, 2011

Hello all,

For a client, I am working on a project where a live RTMP stream is published to an Adobe FMS 3.5.6 server from a java application, using Red5 0.9.1 RTMPClient code.

This works fine, until the timestamp becomes higher than 0xFFFFFF after 4.6 hours, and the RTMP extended timestamp field starts being used. I have already found: when the extended timestamp was written after the header, the last 4 bytes of the data were being cut off. I have fixed this locally, and now the data being sent seems to me to be conformant to the spec. However, FMS still throws an error message in the core log and then kills the connection from the Red5 client. Here is the error message:

This is the error message:

2011-06-03 14:28:02 13060 (e)2611029 Bad network data; terminating connection : chunkstream error:message length 11893407 is longerthan max rtmp packet length - 2011-06-03 14:28:02 13060 (e)2631029 Bad network data; terminating connection : (Adaptor: _defaultRoot_, VHost: _defaultVHost_, IP: 127.0.0.1, App: live/_definst_, Protocol: rtmp, Client: 5290168480216205379, Handle: 2147942405) : 05 FF FF FF 00 13 = 09 01 00 00 00 01 00 01 01 ' 01 00 00 00 00 00 13 4 09 0 00 00 01 ! 9A & L 0F FA F6 12 , B4 A6 CE H 8A AB DC G BB d k 1B 9F ) 13 13 D2 9A E5 t 8 B8 8D 94 ! 8A AE F6 AF } " U 0 D3 Q EF FF ~ 8D 97 D9 FF BE A3 F3 C9 97 o 9D # F9 7F h A4 F7 } / FB & F1 DC 9C BF BD D3 E7 CA 97 FE E2 B9 E4 F7 9E 1A F6 BA } C9 w FC _ / / w FE n EF D7 P 9C F4 BE 82 8E F7 | BE 97 B4 BB D7 FE ED I / FB D1 93 9A F9 X \ 85 BD DD I E3 4 E8 M 13 D3 " ) BE A9 92 E5 83 D4 B4 12 DE D5 A3 E6 F4 k DE BF Q 3 A0 g r A4 f D9 BD w * } F7 r 8A S 2 . AB BD EE ^ l f AF E1 0B $ AF 9D D7 - BF E8 ! D3 } D3 i E3 B8 F2 M A8 " B1 A5 EF s ] A5 BC 96 E5 u e X q D2 F1 r F9 i 92 b EE Z d F9 * A6 BB FD 17 w 4 DD 3 o u EB ] ] EF FE B5 B1 0A F2 A0 DD FD B2 98 DF E8 e F6 CB FD 96 V % A5 D5 k ] FD w EF AF k v AA E8 ! 9F / w BE FA 9A _ E F2 D3 , ? 17 } AD 7 EC B3 } 07 B5 | z { { A5 = 11 90 CF BF ; 4 FE EF 95 F7 E7 DF B9 , AF z 91 CF C9 BD DE CB { F5 17 } F2 E5 D7 DF z E6 [ 96 > Y m 9F EB AF DD D8 E8 v B9 A8 E9 % A7 | 1 CF 8B D Z k N DF F8 N FA S R FE . ~ CB A 9 E1 ) 8F 8E BB EC c 6 13 F1 AC FD FD FC 8A F7 F3 K B9 FA ^ / A4 FC B9 AA F6 DE C2 [ 1A E c r B3 BF E5 EC B5 x 94 FD . A9 t I Q % EA EC DE | K FE z A4 97 F9 " 1 0F CA FB F5 F5 p 9E 99 3 - ; B8 F4 F1 FF t A3 EC BC # DE AC 91 13 19 o < 06 F5 FD 7F 7 _ $ D B t B5 0D 8A C1 C1 BA 0B FE DB B7 83 _ } BD z F7 CB { FC M A9 8D = D5 B1 < 85 = EF E1 ; BA H y FC BC B4 C A2 D9 ` e E4 94 H 5 13 ' 93 93 8E E C2 1C R 97 9 X B7 FF 10 9F { ) F1 CF AB AC ] EE H A2 DE D3 C5 m F6 K A2 A7 A2 89 D2 z EB DF 97 ^ k 9E 99 BB E7 B6 97 w { ~ + C7 B2 } FE ' C4 | B6 o H DD r A8 9F DC FF F9 Q b l 93 T B6 EE FF 11 j CD s P C F1 3 R I F8 D8 R 9D 93 AA D5 + DE FC BE " B9 E1 ` CB BD 0F F5 C7 AA w CF 8D p 9A F7 g f N FF 84 B7 K Q 93 g E1 - D3 s } w v AE 96 98 ED CF BA E9 2 . f 99 95 97 o 13 CA F7 s e $ F4 B5 15 C4 A8 DE M F7 w \ 8D 00 C6 C2 b D3 / 7 w F2 ' BF CD 89 FF > D7 FB BC A2 S N FB A5 CD AF D3 F9 9D DF AE B5 17 CF 9D B7 , B9 9 ^ 7F [ 93 84 F7 } _ EA DF u \ 99 Z t E CA M EF 7 " AD FE 92 9E n 7F EB D8 C { 99 8B 9E w H BF B1 | g 9F F3 FA E1 - E5 CB BB x CF p 8B D2 w v EF w FA E2 F7 s C5 AC $ FC B4 DB BE G E4 DC F0 A0 96 F3 ! t DC FF % A5 CB A4 ^ AB D2 BD E7 9A E ' 08 + AF U 17 EB 8A w A7 N E4 A5 x 93 12 _ - ; 09 DD DF m 11 BE w \ } BA D3 t BC D9 97 9B C5 7F D8 H F1 D 7 8A ^ FA n F0 B8 W E6 84 5 - 8 B5 h o C4 F7 83 P 88 CB AE m t BB L 95 A9 s 90 A2 Y o DF K _ / l D2 D1 C9 91 ' E4 BD / / D 97 m BB E7 14 93 % C5 ; DD CF D8 : ~ B5 4 F FA U F0 8F w w DC FD 83 FC 13 EF w p DA A5 07 _ * - 1D 14 9D D5 84 F E6 F0 FF E4 15 w n A5 9F DE d AE F5 " - f D2 AE 96 1F # FA F1 x C1 L DF l M 06 8A E4 z DB 17 BA l DA e 15 CD 85 86 1F 09 82 h ] C6 { E7 C5 AF Z C5 B0 83 v D9 03 FC / ~ -

The message for which the hex dump is displayed, is a video message of size 4925 bytes. Below is the basic logging in my application:

*** Event sent to RTMP connector: Video - ts: 16777473 length: 4925. Waiting time: -57937, event timestamp: 16777473 14:28:02.045 [RtmpPublisher-workerThread] DEBUG o.r.s.s.consumer.ConnectionConsumer - Message timestamp: 16777473 14:28:02.045 [RtmpPublisher-workerThread] DEBUG o.r.s.n.r.codec.RTMPProtocolEncoder - Channel id: 5 14:28:02.045 [RtmpPublisher-workerThread] DEBUG o.r.s.n.r.codec.RTMPProtocolEncoder - Last ping time for connection: -1 14:28:02.045 [RtmpPublisher-workerThread] DEBUG o.r.s.n.r.codec.RTMPProtocolEncoder - Client buffer duration: 0 14:28:02.046 [RtmpPublisher-workerThread] DEBUG o.r.s.n.r.codec.RTMPProtocolEncoder - Packet timestamp: 16777473; tardiness: -30892; now: 1307104082045; message clock time: 1307104051152, dropLiveFuturefalse 14:28:02.046 [RtmpPublisher-workerThread] DEBUG o.r.s.n.r.codec.RTMPProtocolEncoder - !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!12b Wrote expanded timestamp field 14:28:02.046 [NioProcessor-22] DEBUG o.r.server.net.rtmp.BaseRTMPHandler - Message sent

I have captured the entire frame containing this message with wireshark, and annotated it a bit. You can find it here:

http://pastebin.com/iVtphPgU

The video message of 4925 bytes (hex 00 13 3D) is cut up into chunks of 1024 bytes (chunkSize 1024 set by Red5 client and sent to FMS). Indeed, after the 12-byte header and the 4-byte extended timestamp, there are 1024 bytes before the 1-byte header for the next chunk (hex C5). The chunks after that also contain 1024 bytes after the chunk header. This appears correct to me (though please correct me if I'm wrong).

When we look at the error message in the core log, the hex dump displayed also contains 1024 bytes, but it starts from the beginning of the message header. The last 16 bytes of the message chunk itself are not shown.

My question is this: is the hex dump in the error message always capped to 1024 bytes, or did FMS really read too little data?

Something that may be of help, is the reported 'too long' message length 11893407. This corresponds to hex B5 7A 9F, which can also be found in the packet, namely at row 0c60 (I've annotated it as [b5 7a 9f]. This location is exactly 16 bytes after the start of the 4th chunk data, not really a place to look for timestamps.

My assumptions during this bug hunting session were the following (would be nice if someone could validate these for me):

- message length, as specified in the RTMP 12 and 8-bit headers, defines the total number of data bytes for the message, NOT including the header of the first message chunk, its extended timestamp field, or the 1-byte headers for subsequent chunks. The behaviour is the same whether or not the message has an extended timestamp.

- chunk size, as set by the chunkSize message, defines the total number of data bytes for the chunk, not incuding the header or extended timestamp field. The behaviour is the same whether or not the message has an extended timestamp.

I believe I've chased this problem as far as I can without having access to the FMS 3.5 code, or at least being able to crank up the debug logging to the per-message level. I realize it's a pretty detailed issue and a long shot, but being able to publish a stream continuously 24/7 is critical for the project.

I would be very grateful if someone could have a look at this hex dump to see if the message itself is correct, and if so, to have a look at how FMS3.5.6 handles this.

Don't hesitate to ask me for more info if it can help.

Thanks in advance

Davy Herben

Solidity

Report · Jun 09, 2011

Hi,

Thanks for the very detail. I smell some issue here. We also have few similar issues reported from elsewhere though they might not exactly be the same.

I would spend more time on this, but for now , we are actively tracking this internally to find out if there is any root cause for the bad network data problems.

The issue seems that either FMS are not receiving some data, or some erroneous condition is being hit, which is making it to start dechunking a chunk at some point within the chunk(here it is 13 bytes after the chunk header), which is causing the FMS Code to treat some video data as the chunk header. This erroneous header then returns some big length of the chunk, which causes the problem to be seen in the core logs.

Regarding your claims that some bytes are missing in the core logs from the first chunk. This is because, our logging mechanism basically logs a maximum of 1024 bytes, and hence, in this case, is missing the last 16 bytes of the first chunk, as it logs the 16 byte chunk header in the beginning.

Are you able to reproduce this 100% ? can you share that part of your client/code that can reproduce this with us, so that we could use, if it is ok ?

Thanks very much for your co-operation.

Report · Jun 09, 2011

Hello Nikhil,

Thank you very much for your interest in this issue. Yes I can reproduce it here 100%.

I will write up a test case which reproduces the issue and send it to you tomorrow.

Thanks for clarifying the logging behaviour.

Kind regards,

Davy

Report · Jun 13, 2011

Hello,

It took a bit longer than expected, but I have managed to create a minimal test application that will reproduce the error condition on all machines I've tested on. The application will simply read an H264 file and publish it to an FMS as a live stream. To hit the error condition faster, without having to wait 4.6 hours, the application will add a fixed offset to all timestamps before sending it to the FMS.

I have created two files:

http://www.solidity.be/publishtest.jar : Runnable java archive with all libraries built in

http://www.solidity.be/publishtest.zip : Zip file containing sources and libraries

You can run the jar as follows:

java -jar publishtest.jar <inputFile> <server> <port> <application> <stream> <timestampOffset>

- inputFile: path to an H264 input video file

- server: hostname or IP of FMS server to publish to

- port: port number to publish to (1935)

- application: application to publish to (live)

- stream: stream to publish to (output)

- timestampOffset: nr of milliseconds to add to the timestamp of each event, in hexadecimal format. Putting FFFFFF here will cause the server to reject the connection immediately, while FFFF00 or FFF000 will allow the publishing to run for awhile before the FMS kills it

Example of a complete command line:

java -jar publishtest.jar /home/myuser/Desktop/movie.mp4 localhost 1935 live output FFF000

Good luck with the bug hunting. Let me know if there is anything I can help you with.

Kind regards,

Davy Herben

Report · Jun 13, 2011

Thank you very much for the detailed information and the files. We would start looking at this issue right away and i will update you soon.

Report · Jun 28, 2011

Hi,

Any news on this yet?

Thx,

Davy

Report · Jun 28, 2011

Hi Davy,

Sorry that we couldn't update you on this so far. I have seen it reproduced with the files you provided but I could not escalate the issue soon causing the delay. We are in the process of investigating this , and i can let you know once there issue is found.

We apprecite your patience on this. Thank you !

Adobe Community

FMS 3.5 says 'Bad network data': error in handling RTMP extended timestamps / chunkSize?