Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Finalization of flv file failed #11

Open
dAnjou opened this issue Feb 18, 2015 · 15 comments
Open

Finalization of flv file failed #11

dAnjou opened this issue Feb 18, 2015 · 15 comments
Assignees

Comments

@dAnjou
Copy link

dAnjou commented Feb 18, 2015

Hi,

our Red5 1.0.5 has trouble finalizing the FLVs. We were using 0.9RC before where it worked. We upgraded to 1.0.5 for native RTMPS support (which works). We're pretty much using the default Red5 settings. The client is a self-made Flash application, I'd rather not post the code, it's kinda messy but as I said, it worked with 0.9RC before.

Oh, it happens every single time, not just once in a while, So, this doesn't really help us: https://github.com/Red5/red5-server/wiki/Repairing-Recordings

I'd appreciate any pointers on how to debug this! Thanks.

This is what is received:

-rw-r--r-- 1 vagrant www-data 3.3M Feb 18 21:28 test-1404259686lu-1-v0.flv.ser
-rw-r--r-- 1 vagrant www-data   32 Feb 18 21:28 test-1404259686lu-1-v0.flv.info
-rw-r--r-- 1 vagrant www-data  51K Feb 18 21:28 test-1404259686lu-1-a0.flv.ser
-rw-r--r-- 1 vagrant www-data   32 Feb 18 21:28 test-1404259686lu-1-a0.flv.info
-rw-r--r-- 1 vagrant www-data  212 Feb 18 21:28 test-1404259686lu-1-v0.flv
-rw-r--r-- 1 vagrant www-data  276 Feb 18 21:28 test-1404259686lu-1-a0.flv

The following commands produce perfectly fine audio/video streams:

cat test-1404259686lu-1-a0.flv test-1404259686lu-1-a0.flv.ser > a.flv
cat test-1404259686lu-1-v0.flv test-1404259686lu-1-v0.flv.ser > v.flv

And here's the error.log (Das Argument ist ungültig means Invalid argument):

2015-02-18 21:28:40,181 [RTMPConnectionExecutor#G38NKTJWLA6LA-1] WARN  org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.io.IOException: Das Argument ist ungültig
    at sun.nio.ch.FileChannelImpl.map0(Native Method) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:893) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:601) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:675) ~[na:1.8.0_40-internal]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:737) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter.close(FLVWriter.java:856) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.server.stream.consumer.FileConsumer.uninit(FileConsumer.java:502) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.RecordingListener.stop(RecordingListener.java:237) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:209) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_40-internal]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_40-internal]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_40-internal]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_40-internal]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server-common-1.0.5-RELEASE.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:269) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:105) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:57) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_40-internal]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_40-internal]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40-internal]
2015-02-18 21:28:40,230 [RTMPConnectionExecutor#G38NKTJWLA6LA-1] WARN  o.r.s.stream.consumer.FileConsumer - Exception waiting for write result. Timeout: 15000ms
java.lang.InterruptedException: null
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:404) [na:1.8.0_40-internal]
    at java.util.concurrent.FutureTask.get(FutureTask.java:204) [na:1.8.0_40-internal]
    at org.red5.server.stream.consumer.FileConsumer.acquireWriteFuture(FileConsumer.java:370) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.consumer.FileConsumer.writeQueuedDataSlice(FileConsumer.java:284) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.consumer.FileConsumer.pushMessage(FileConsumer.java:275) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.RecordingListener.processQueue(RecordingListener.java:303) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.RecordingListener.stop(RecordingListener.java:234) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:209) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_40-internal]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_40-internal]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_40-internal]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_40-internal]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server-common-1.0.5-RELEASE.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:269) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:105) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:57) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_40-internal]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_40-internal]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40-internal]
2015-02-18 21:28:41,468 [RTMPConnectionExecutor#G38NKTJWLA6LA-1] WARN  org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.io.IOException: Das Argument ist ungültig
    at sun.nio.ch.FileChannelImpl.map0(Native Method) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:893) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:601) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:675) ~[na:1.8.0_40-internal]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:737) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter.close(FLVWriter.java:856) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.server.stream.consumer.FileConsumer.uninit(FileConsumer.java:502) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.RecordingListener.stop(RecordingListener.java:237) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:209) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_40-internal]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_40-internal]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_40-internal]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_40-internal]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server-common-1.0.5-RELEASE.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:269) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:105) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:57) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server-common-1.0.5-RELEASE.jar:1.0.5-RELEASE]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_40-internal]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_40-internal]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_40-internal]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40-internal]
2015-02-18 21:28:42,214 [FLVFinalizer#1424291320187] WARN  org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.io.IOException: Das Argument ist ungültig
    at sun.nio.ch.FileChannelImpl.map0(Native Method) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:893) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:601) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:675) ~[na:1.8.0_40-internal]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:737) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter.access$400(FLVWriter.java:54) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter$FLVFinalizer.run(FLVWriter.java:974) [red5-io-1.0.5-RELEASE.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40-internal]
2015-02-18 21:28:43,485 [FLVFinalizer#1424291321469] WARN  org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.io.IOException: Das Argument ist ungültig
    at sun.nio.ch.FileChannelImpl.map0(Native Method) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:893) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:601) ~[na:1.8.0_40-internal]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:675) ~[na:1.8.0_40-internal]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:737) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter.access$400(FLVWriter.java:54) [red5-io-1.0.5-RELEASE.jar:na]
    at org.red5.io.flv.impl.FLVWriter$FLVFinalizer.run(FLVWriter.java:974) [red5-io-1.0.5-RELEASE.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_40-internal]
@mondain
Copy link
Member

mondain commented Feb 18, 2015

We're not sure why this happens on some flvs, but there is a workaround here: https://github.com/Red5/red5-server/wiki/Repairing-Recordings

@dAnjou
Copy link
Author

dAnjou commented Feb 19, 2015

That's a bummer ...

The workaround (I knew about it) is not really feasible for us because it happens for every single recording.

@dAnjou
Copy link
Author

dAnjou commented Mar 6, 2015

Here's an interesting observation: the setup where the issue occurred was a VirtualBox VM and the streams were written to a shared folder. Then I was testing something else in a different VM. This time the streams folder was not shared and it worked.

Isn't that mysterious?

@mikesheppard
Copy link

Thanks letting everyone know dAnjou!

Exactly the same problem here with Red5 not finalizing the FLV's when it was running in a vagrant shared folder. Moved the folder elsewhere and it worked perfectly. I am running Red5 1.0.4.

@mondain
Copy link
Member

mondain commented Aug 26, 2015

I would assume this has something to do with shared folders then; if anyone has a fix or a suggestion to work around this then please create a pull request.

@mondain mondain closed this as completed Aug 26, 2015
@octavn
Copy link

octavn commented Dec 15, 2015

We have stumbled over the same warning several times:

From my experience it only happens with big files of 100-150 MB. Red5 is running on a DigitalOcean VPS with CentOS 6.5.

2015-12-14 06:32:18,938 [RTMPExecutor#PCVU7WR84UAUD-1] INFO  VideoRecorder.Application - W3C x-category:stream x-event:record-stop c-ip:86.35.242.133 x-sname:b44e1950-0976-4771-96d3-7770eedda326 x-file-name:vs1450087575474_918.flv
2015-12-14 06:32:18,940 [RTMPExecutor#PCVU7WR84UAUD-1] DEBUG o.r.server.stream.RecordingListener - Event queue was empty on stop
2015-12-14 06:32:19,436 [Thread-13199474] INFO  o.r.s.net.rtmp.ReceivedMessageTask - Interrupting unfinished task on PCVU7WR84UAUD
2015-12-14 06:32:19,476 [RTMPExecutor#PCVU7WR84UAUD-1] WARN  org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.nio.channels.ClosedByInterruptException: null
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:290) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:609) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:666) ~[na:1.7.0_75]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:597) [red5-io-1.0.3.jar:na]
    at org.red5.io.flv.impl.FLVWriter.close(FLVWriter.java:716) [red5-io-1.0.3.jar:na]
    at org.red5.server.stream.consumer.FileConsumer.uninit(FileConsumer.java:482) [red5-server.jar:na]
    at org.red5.server.stream.RecordingListener.stop(RecordingListener.java:237) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:209) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server.jar:na]
    at sun.reflect.GeneratedMethodAccessor508.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:268) [red5-server.jar:na]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:89) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:54) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server.jar:na]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
2015-12-14 06:32:19,476 [RTMPExecutor#PCVU7WR84UAUD-1] INFO  org.red5.io.flv.impl.FLVWriter - Spawning flv finalizer for /opt/red5-server-1.0.3-SNAPSHOT_with_recording_fixed/webapps/hdfvr/streams/_definst_/vs1450087575474_918.flv
2015-12-14 06:32:19,478 [RTMPExecutor#PCVU7WR84UAUD-1] WARN  o.r.s.net.rtmp.RTMPMinaConnection - Interrupted while waiting for write lock. State: connected
java.lang.InterruptedException: null
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325) ~[na:1.7.0_75]
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:414) ~[na:1.7.0_75]
    at org.red5.server.net.rtmp.RTMPMinaConnection.write(RTMPMinaConnection.java:366) ~[red5-server.jar:na]
    at org.red5.server.net.rtmp.Channel.write(Channel.java:136) [red5-server.jar:na]
    at org.red5.server.net.rtmp.Channel.sendStatus(Channel.java:190) [red5-server.jar:na]
    at org.red5.server.stream.consumer.ConnectionConsumer.pushMessage(ConnectionConsumer.java:127) [red5-server.jar:na]
    at org.red5.server.messaging.InMemoryPushPushPipe.pushMessage(InMemoryPushPushPipe.java:81) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.pushMessage(ClientBroadcastStream.java:759) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.sendPublishStopNotify(ClientBroadcastStream.java:707) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:211) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server.jar:na]
    at sun.reflect.GeneratedMethodAccessor508.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:268) [red5-server.jar:na]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:89) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:54) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server.jar:na]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
2015-12-14 06:32:19,478 [RTMPExecutor#PCVU7WR84UAUD-1] INFO  VideoRecorder.Application - W3C x-category:stream x-event:unpublish c-ip:86.35.242.133 cs-bytes:320153465 sc-bytes:5428 x-sname:b44e1950-0976-4771-96d3-7770eedda326 x-file-length:5163 x-name:vs1450087575474_918
2015-12-14 06:32:19,478 [RTMPExecutor#PCVU7WR84UAUD-1] INFO  VideoRecorder.Application - W3C x-category:stream x-event:recordstop c-ip:86.35.242.133 cs-bytes:320153465 sc-bytes:5428 x-sname:b44e1950-0976-4771-96d3-7770eedda326 x-file-name:vs1450087575474_918.flv x-file-length:5163 x-file-size:320153465
2015-12-14 06:32:19,485 [FLVFinalizer#1450092739476] INFO  org.red5.io.flv.impl.FLVWriter - Deleted (true) incomplete file: /opt/red5-server-1.0.3-SNAPSHOT_with_recording_fixed/webapps/hdfvr/streams/_definst_/vs1450087575474_918.flv

The vs1450087575474_918.flv in particular had 300MB.

For future reference here's the file/code with the warning:
https://github.com/Red5/red5-io/blob/master/src/main/java/org/red5/io/flv/impl/FLVWriter.java

Line 876:

} catch (Exception e) {
    log.warn("Finalization of flv file failed; new finalize job will be spawned", e);
}

@octavn
Copy link

octavn commented Dec 15, 2015

I can consistently trigger the issue by recording 10 minutes of HD (1280x720) video. I just recorded a 10:21 video which resulted in a .flv.ser file of 146,5 MB (I used a recent MacBook Air's webcam and the bitrate is 1.88Mbits/s).

These are the 3 files created by Red5 including the .flv.ser:

-rw-r--r--  1 nike  staff        300 Dec 15 15:38 vs1450185683776_290.flv
-rw-r--r--  1 nike  staff         32 Dec 15 15:38 vs1450185683776_290.flv.info
-rw-r--r--  1 nike  staff  146495129 Dec 15 15:38 vs1450185683776_290.flv.ser

Using the above mentioned cat command helped produce a .flv file which plays in VLC but looking at the flv's Media Information > Codec Details window it shows 52 streams mostly various audio and video types but also 2 subtitle streams:

Media Information

@mondain
Copy link
Member

mondain commented Dec 15, 2015

What codecs and publishing (to red5) are you using for the test?

@mondain mondain reopened this Dec 15, 2015
@octavn
Copy link

octavn commented Dec 15, 2015

We're using H.264 for video and Nellymoser for audio.

Just to be clear the above image is taken with a .flv created with:
cat vs1450185683776_290.flv vs1450185683776_290.flv.ser > a.flv

@mondain
Copy link
Member

mondain commented Dec 15, 2015

The flv and ser aren't meant to be combined; the finalizer uses .info and .ser to construct the flv and it also does some processing if memory serves.

@octavn
Copy link

octavn commented Dec 15, 2015

Oh yeah I know, I just brought it up because others reading this thread might consider the cat command mentioned by @dAnjou a solution.

@octavn
Copy link

octavn commented Mar 4, 2016

The issue also has something to do with either the length of the video (more likely) or with the size (less likely).

From 12 videos I just recorded, most were under 40 seconds long, but 3 of them were between 7 and 8 minutes. All 3 of them failed with the same error:

[WARN] [RTMPExecutor#7P6WE5RG6WJOY-1] org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned

creating a tiny .flv file, .flv.info and big .flv.ser files.

In terms of size they occupied 42MB, 71MB and 80MB respectively. In the past we recorded 120MB files without any issues that's why I'm saying it's not necessarily size related..

I managed to recover the videos using https://github.com/Red5/red5-server/wiki/Repairing-Recordings . Here's the command I used in Windows' Command Prompt with Red5 1.0.6 (videos were recorded with 1.0.3).

java -cp "C:\Red51.0.6\red5-server.jar;C:\Red51.0.6\lib\red5-io-1.0.6-RELEASE.jar;C:\Red51.0.6\lib\slf4j-api-1.7.9.jar;C:\Red51.0.6\lib\logback-core-1.1.2.jar;C:\Red51.0.6\lib\logback-classic-1.1.2.jar;C:\Red51.0.6\lib\mina-core-2.0.9.jar;C:\Red51.0.6\lib\ehcache-core-2.6.9.jar" org.red5.io.flv.impl.FLVWriter "C:\Users\PcBig\Desktop\large vids\video_738.flv.ser" 6 7

6 is the CodecID for Nellymoser audio, 7 is the CodecID for H.264/AVC video which is what I used when recording. You can find the CodecID numbers in the flv spec pages 6 and 8.

The command basically triggers the repair function in org.red5.io.flv.impl.FLVWriter

Allows repair of flv files if .info and .ser files still exist.

@octavn
Copy link

octavn commented Mar 4, 2016

The actual line in org.red5.io.flv.impl.FLVWriter where the exception happens is:

// transfer / write data file into final flv                
bytesTransferred = file.getChannel().transferFrom(dataFile.getChannel(), bytesWritten, dataFile.length());
java.nio.channels.ClosedByInterruptException: null
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:290) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:609) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:666) ~[na:1.7.0_75]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:597) [red5-io-1.0.3.jar:na]

@mondain mondain self-assigned this Mar 4, 2016
@octavn
Copy link

octavn commented Mar 7, 2016

Our stack trace is a bit different than the one posted at the top. Maybe because we're running Red5 1.0.3 ? In our case the exception seems to be thrown by the end() function in java.nio.channels.spi.AbstractInterruptibleChannel

[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.ClientBroadcastStream - Stream start: vs1457355476845_97
[DEBUG] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.RecordingListener - Recording file: /opt/red51.0.3/webapps/hdfvr/streams/_definst_/vs1457355476845_97.flv
[DEBUG] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.RecordingListener - Context contains a file consumer
[DEBUG] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.RecordingListener - File name: vs1457355476845_97.flv
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] VideoRecorder.Application - W3C x-category:stream x-event:record-start c-ip:86.35.242.133 x-sname:6762966d-792f-4b8e-9a18-4a5f4ed01020 x-file-name:vs1457355476845_97.flv
[DEBUG] [Red5_Scheduler_Worker-31] org.red5.server.stream.RecordingListener - Stream data size was 0, sending empty audio message
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.StreamService - closeStream: streamId=1, connection=RTMPMinaConnection from 86.35.242.133 (in: 73335450 out: 4114) session: SLC0EPPXT06JD state: connected
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] VideoRecorder.Application - W3C x-category:stream x-event:record-stop c-ip:86.35.242.133 x-sname:6762966d-792f-4b8e-9a18-4a5f4ed01020 x-file-name:vs1457355476845_97.flv
[DEBUG] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.stream.RecordingListener - Event queue was empty on stop
[INFO] [Thread-54332526] org.red5.server.net.rtmp.ReceivedMessageTask - Interrupting unfinished task on SLC0EPPXT06JD
[WARN] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.nio.channels.ClosedByInterruptException: null
    at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.position(FileChannelImpl.java:290) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFromFileChannel(FileChannelImpl.java:609) ~[na:1.7.0_75]
    at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:666) ~[na:1.7.0_75]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:597) [red5-io-1.0.3.jar:na]
    at org.red5.io.flv.impl.FLVWriter.close(FLVWriter.java:716) [red5-io-1.0.3.jar:na]
    at org.red5.server.stream.consumer.FileConsumer.uninit(FileConsumer.java:482) [red5-server.jar:na]
    at org.red5.server.stream.RecordingListener.stop(RecordingListener.java:237) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:209) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_75]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_75]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:268) [red5-server.jar:na]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:89) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:54) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server.jar:na]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.io.flv.impl.FLVWriter - Spawning flv finalizer for /opt/red51.0.3/webapps/hdfvr/streams/_definst_/vs1457355476845_97.flv
[INFO] [FLVFinalizer#1457355779901] org.red5.io.flv.impl.FLVWriter - Deleted (true) incomplete file: /opt/red51.0.3/webapps/hdfvr/streams/_definst_/vs1457355476845_97.flv
[WARN] [RTMPExecutor#SLC0EPPXT06JD-1] org.red5.server.net.rtmp.RTMPMinaConnection - Interrupted while waiting for write lock. State: connected
java.lang.InterruptedException: null
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325) ~[na:1.7.0_75]
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:414) ~[na:1.7.0_75]
    at org.red5.server.net.rtmp.RTMPMinaConnection.write(RTMPMinaConnection.java:366) ~[red5-server.jar:na]
    at org.red5.server.net.rtmp.Channel.write(Channel.java:136) [red5-server.jar:na]
    at org.red5.server.net.rtmp.Channel.sendStatus(Channel.java:190) [red5-server.jar:na]
    at org.red5.server.stream.consumer.ConnectionConsumer.pushMessage(ConnectionConsumer.java:127) [red5-server.jar:na]
    at org.red5.server.messaging.InMemoryPushPushPipe.pushMessage(InMemoryPushPushPipe.java:81) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.pushMessage(ClientBroadcastStream.java:759) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.sendPublishStopNotify(ClientBroadcastStream.java:707) [red5-server.jar:na]
    at org.red5.server.stream.ClientBroadcastStream.close(ClientBroadcastStream.java:211) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:156) [red5-server.jar:na]
    at org.red5.server.stream.StreamService.closeStream(StreamService.java:112) [red5-server.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_75]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_75]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_75]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_75]
    at org.red5.server.service.ServiceInvoker.invoke(ServiceInvoker.java:193) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.invokeCall(RTMPHandler.java:210) [red5-server.jar:na]
    at org.red5.server.net.rtmp.RTMPHandler.onCommand(RTMPHandler.java:268) [red5-server.jar:na]
    at org.red5.server.net.rtmp.BaseRTMPHandler.messageReceived(BaseRTMPHandler.java:89) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:54) [red5-server.jar:na]
    at org.red5.server.net.rtmp.ReceivedMessageTask.call(ReceivedMessageTask.java:11) [red5-server.jar:na]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_75]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_75]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_75]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] VideoRecorder.Application - W3C x-category:stream x-event:unpublish c-ip:86.35.242.133 cs-bytes:73335464 sc-bytes:4259 x-sname:6762966d-792f-4b8e-9a18-4a5f4ed01020 x-file-length:304 x-name:vs1457355476845_97
[INFO] [RTMPExecutor#SLC0EPPXT06JD-1] VideoRecorder.Application - W3C x-category:stream x-event:recordstop c-ip:86.35.242.133 cs-bytes:73335464 sc-bytes:4259 x-sname:6762966d-792f-4b8e-9a18-4a5f4ed01020 x-file-name:vs1457355476845_97.flv x-file-length:304 x-file-size:73335464
[WARN] [FLVFinalizer#1457355779901] org.red5.io.flv.impl.FLVWriter - Finalization of flv file failed; new finalize job will be spawned
java.io.IOException: Stream Closed
    at java.io.RandomAccessFile.seek(Native Method) ~[na:1.7.0_75]
    at org.red5.io.flv.impl.FLVWriter.finalizeFlv(FLVWriter.java:595) [red5-io-1.0.3.jar:na]
    at org.red5.io.flv.impl.FLVWriter.access$400(FLVWriter.java:54) [red5-io-1.0.3.jar:na]
    at org.red5.io.flv.impl.FLVWriter$FLVFinalizer.run(FLVWriter.java:834) [red5-io-1.0.3.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_75]
[ERROR] [NioProcessor-7] org.red5.server.scope.Scope - Error while executing "leave" for client RTMPMinaConnection from 86.35.242.133 (in: 73335471 out: 4266) session: SLC0EPPXT06JD state: disconnecting on handler VideoRecorder.Application@19ce34a. java.lang.NullPointerException
[INFO] [NioProcessor-7] VideoRecorder.Application - W3C x-category:session x-event:disconnect c-ip:86.35.242.133 c-client-id:36025

@octavn
Copy link

octavn commented Mar 7, 2016

Looking at another batch.

From 2701 videos recorded over 4 months with Red5 1.0.3, 21 of them had this issue.

20 of them are between 12.8MB and 81.2MB while the 21st is 149.1MB in size.

From the top 20 biggest files recorded, they occupy 14 positions including the 1st 6:
screenshot 2016-03-07 21 19 55

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants