FMS 3.5 says 'Bad network data': error in handling RTMP extended timestamps / chunkSize?
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:
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
AdChoices