Ticket #714 (closed Bug: Fixed)

Opened 23 months ago

Last modified 18 months ago

Problems recording FLV in rev. 4074

Reported by: rhys04 Owned by: mondain
Priority: Major Component: Streaming and Networking
Version: Keywords:
Cc: aarond10ster@…, tmw@…

Description

I'm testing revision 4074, and it seems like something is going wrong in the FLV recording sometimes (seems random). When I start recording, I sometimes get this message in the Red5 log:

[INFO] [NioProcessor-1] org.red5.server.stream.ClientBroadcastStream - Consumer
connect
Exception in thread "Thread-3" java.lang.IllegalArgumentException

at java.nio.Buffer.position(Buffer.java:218)
at sun.nio.ch.IOUtil.write(IOUtil.java:78)
at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:206)
at org.red5.io.flv.impl.FLVWriter.writeTag(FLVWriter.java:254)
at org.red5.server.stream.consumer.FileConsumer.write(FileConsumer.java:

330)

at org.red5.server.stream.consumer.FileConsumer.doWrites(FileConsumer.ja

va:290)

at org.red5.server.stream.consumer.FileConsumer$1.run(FileConsumer.java:

172)

If this happens, the recorded FLV is unplayable. It only happens sometimes - I've tried about 20 recordings, and it's happened 2 times so far.

It also complains when I stop the recording, but it doesn't seem to have any effect on the recorded FLV. This error happens every time, so is easily reproducible. Here's the error:

[ERROR] [NioProcessor-1] org.red5.server.messaging.AbstractPipe - exception when
handling pipe connection event
java.lang.NullPointerException: null

at org.red5.server.stream.ClientBroadcastStream.onPipeConnectionEvent(Cl

ientBroadcastStream.java:482) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.firePipeConnectionEvent(Abstra

ctPipe.java:258) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.fireProviderConnectionEvent(Ab

stractPipe.java:248) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.unsubscribe(AbstractPipe.java:

111) [red5.jar:na]

at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStr

eam.java:200) [red5.jar:na]

at org.red5.server.stream.StreamService.closeStream(StreamService.java:7

5) [red5.jar:na]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0

_10]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.

java:39) [na:1.6.0_10]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces

sorImpl.java:25) [na:1.6.0_10]

at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_10]
at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:200

) [red5.jar:na]

at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:185)

[red5.jar:na]

at org.red5.server.net.rtmp.RTMPHandler.onInvoke(RTMPHandler.java:393) [

red5.jar:na]

at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHand

ler.java:138) [red5.jar:na]

at org.red5.server.net.rtmp.RTMPMinaIoHandler.messageReceived(RTMPMinaIo

Handler.java:180) [red5.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.mess

ageReceived(DefaultIoFilterChain.java:713) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.red5.server.net.filter.TrafficShapingFilter.messageReceived(Traff

icShapingFilter.java:204) [red5.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutpu

tImpl.flush(ProtocolCodecFilter.java:383) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(Prot

ocolCodecFilter.java:229) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFi

lterAdapter.java:119) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageRece

ived(DefaultIoFilterChain.java:426) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(Abstract

PollingIoProcessor.java:708) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(Abstr

actPollingIoProcessor.java:665) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(Abstr

actPollingIoProcessor.java:654) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(Ab

stractPollingIoProcessor.java:64) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run

(AbstractPollingIoProcessor.java:1111) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnabl

e.java:64) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExec

utor.java:886) [na:1.6.0_10]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor

.java:908) [na:1.6.0_10]

at java.lang.Thread.run(Thread.java:619) [na:1.6.0_10]

[WARN] [NioProcessor-1] org.red5.server.stream.consumer.FileConsumer - Tag was n
ot written
[INFO] [NioProcessor-1] org.red5.server.stream.ClientBroadcastStream - Provider
disconnect
[ERROR] [NioProcessor-1] org.red5.server.messaging.AbstractPipe - exception when
handling pipe connection event
java.lang.NullPointerException: null

at org.red5.server.stream.ClientBroadcastStream.onPipeConnectionEvent(Cl

ientBroadcastStream.java:482) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.firePipeConnectionEvent(Abstra

ctPipe.java:258) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.fireProviderConnectionEvent(Ab

stractPipe.java:248) [red5.jar:na]

at org.red5.server.messaging.AbstractPipe.unsubscribe(AbstractPipe.java:

111) [red5.jar:na]

at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStr

eam.java:209) [red5.jar:na]

at org.red5.server.stream.StreamService.closeStream(StreamService.java:7

5) [red5.jar:na]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0

_10]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.

java:39) [na:1.6.0_10]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces

sorImpl.java:25) [na:1.6.0_10]

at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_10]
at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:200

) [red5.jar:na]

at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:185)

[red5.jar:na]

at org.red5.server.net.rtmp.RTMPHandler.onInvoke(RTMPHandler.java:393) [

red5.jar:na]

at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHand

ler.java:138) [red5.jar:na]

at org.red5.server.net.rtmp.RTMPMinaIoHandler.messageReceived(RTMPMinaIo

Handler.java:180) [red5.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.mess

ageReceived(DefaultIoFilterChain.java:713) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.red5.server.net.filter.TrafficShapingFilter.messageReceived(Traff

icShapingFilter.java:204) [red5.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutpu

tImpl.flush(ProtocolCodecFilter.java:383) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(Prot

ocolCodecFilter.java:229) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(Def

aultIoFilterChain.java:46) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.mes

sageReceived(DefaultIoFilterChain.java:793) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na
]

at org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFi

lterAdapter.java:119) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessage

Received(DefaultIoFilterChain.java:434) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageRece

ived(DefaultIoFilterChain.java:426) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(Abstract

PollingIoProcessor.java:708) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(Abstr

actPollingIoProcessor.java:665) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(Abstr

actPollingIoProcessor.java:654) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(Ab

stractPollingIoProcessor.java:64) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run

(AbstractPollingIoProcessor.java:1111) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnabl

e.java:64) [mina-core-2.0.0-RC2-SNAPSHOT.jar:na]

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExec

utor.java:886) [na:1.6.0_10]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor

.java:908) [na:1.6.0_10]

at java.lang.Thread.run(Thread.java:619) [na:1.6.0_10]

Change History

Changed 23 months ago by nleonard

It seems to be related - I just had this one:

[INFO] [NioProcessor-1] org.red5.server.stream.ClientBroadcastStream - Consumer connect
Exception in thread "Thread-33" java.nio.BufferOverflowException

at java.nio.DirectByteBuffer.put(Unknown Source)
at java.nio.DirectByteBuffer.put(Unknown Source)
at sun.nio.ch.IOUtil.write(Unknown Source)
at sun.nio.ch.FileChannelImpl.write(Unknown Source)
at org.red5.io.flv.impl.FLVWriter.writeTag(FLVWriter.java:254)
at org.red5.server.stream.consumer.FileConsumer.write(FileConsumer.java:333)
at org.red5.server.stream.consumer.FileConsumer.doWrites(FileConsumer.java:292)
at org.red5.server.stream.consumer.FileConsumer$1.run(FileConsumer.java:180)

Changed 22 months ago by anebi

I have the same problem with red5 0.9.1. When i use demos/publisher and try to record a live stream, i get 

# Exception in thread "Thread-4" java.nio.BufferOverflowException
	at java.nio.DirectByteBuffer.put(DirectByteBuffer.java:329)
	at java.nio.DirectByteBuffer.put(DirectByteBuffer.java:308)
	at sun.nio.ch.IOUtil.write(IOUtil.java:88)
	at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:224)
	at org.red5.io.flv.impl.FLVWriter.writeTag(FLVWriter.java:254)
	at org.red5.server.stream.consumer.FileConsumer.write(FileConsumer.java:333)
	at org.red5.server.stream.consumer.FileConsumer.doWrites(FileConsumer.java:292)
	at org.red5.server.stream.consumer.FileConsumer$1.run(FileConsumer.java:180)
Exception in thread "Thread-6" java.lang.IllegalArgumentException
	at java.nio.Buffer.position(Buffer.java:235)
	at sun.nio.ch.IOUtil.write(IOUtil.java:96)
	at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:224)
	at org.red5.io.flv.impl.FLVWriter.writeTag(FLVWriter.java:254)
	at org.red5.server.stream.consumer.FileConsumer.write(FileConsumer.java:333)
	at org.red5.server.stream.consumer.FileConsumer.doWrites(FileConsumer.java:292)
	at org.red5.server.stream.consumer.FileConsumer$1.run(FileConsumer.java:180)

The file is created, but it is unusable. I cannot play this flv file from demo applications nor from flowplayer.

If i start recording using Simple Recorder demo application, then this recorded FLV file is ok and i can play it. I hope this information will help this problem to be solved.

Changed 21 months ago by aarond10

  • cc aarond10ster@… added

I wonder if this patch might help?

I noticed some weird streams too but didn't have the associated logs at the time. It looks like the FLV tag headers and data just plain don't match up sometimes. Audio streams with 104 bytes according to their header only contain 100 bytes or less. Other times its fine. I traced this bug down where it seems possible that on a loaded system (EC2 in my case) multiple file writer worker threads could be opened for the one file. I figured that was a silly thing to do so I've patched it (diff applied to 0.9.1 tag in SVN).

Index: src/org/red5/server/stream/consumer/FileConsumer.java
===================================================================
--- src/org/red5/server/stream/consumer/FileConsumer.java (revision 4092)
+++ src/org/red5/server/stream/consumer/FileConsumer.java (working copy)
@@ -114,6 +114,11 @@

private int queueThreshold = 33;

/**

+ * Worker thread
+ */
+ private Thread worker = null;
+
+ /**

  • Creates file consumer
  • @param scope Scope of consumer
  • @param file File

@@ -173,8 +178,8 @@

queue.add(queued);

//when we reach the threshold, spawn a write thread

- if (queue.size() >= queueThreshold) {
- Thread worker = new Thread() {
+ if (queue.size() >= queueThreshold && worker == null) {
+ worker = new Thread() {

public void run() {

log.debug("Spawning queue writer thread");
doWrites();

@@ -441,4 +446,4 @@

}

-}
\ No newline at end of file
+}

Changed 21 months ago by aarond10

One other thing. I don't understand why this class is waiting before starting that worker thread. There are no other code paths I can see that lead to writes so shouldn't it just start the thread immediately?? Just an observation. I maybe missed something. :)

Changed 20 months ago by tim_mw

  • cc tmw@… added

Changed 18 months ago by mondain

  • status changed from new to closed
  • resolution set to Fixed

There should be no way for the workers to clash with the latest revision (4138) there is however still an issue with the flv output but that is not what this bug is about.

Note: See TracTickets for help on using tickets.