search

Red5 / red5-io

Red5 I/O library
Apache License 2.0
80 stars 80 forks source link

Finalization of flv file failed #11

Open dAnjou opened 9 years ago

dAnjou commented 9 years ago

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 commented 9 years ago

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 commented 9 years ago

That's a bummer ...

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

dAnjou commented 9 years ago

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 commented 9 years ago

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 commented 9 years ago

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.

octavn commented 8 years ago

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 commented 8 years ago

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 commented 8 years ago

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

octavn commented 8 years ago

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 commented 8 years ago

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 commented 8 years ago

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 commented 8 years ago

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 commented 8 years ago

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]
octavn commented 8 years ago

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 commented 8 years ago

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