Bug Report Stream ends immediately instead of finishing delayed stream

[Boildown]

Not sure how to describe this with a more meaningful subject line...

Using version 0.541b, and also in the previous test build.

I stream with a 15 minute delay (Broadcast Settings > Delay (seconds) set to 900).

When I end the stream, the expected behavior is for it to continue to stream for 900 more seconds, until all the cached stream has been sent. What often (but not always) happens is it ends immediately and thinks it has disconnected from the server, the 10 second auto-reconnect timeout ticks down, and if not manually stopped, starts a whole new stream again.

This usually happens when I've been streaming for a "long" time, where "long" is something on the order of 2-3 hours or longer. Less than 2 hours, it usually behaves as expected. Longer than 3 hours, it almost always does the bug as described. Between 2 to 3 hours its more of a mixed bag. Most of my experience with this is from the last few test builds, but I just saw it last night in the .541b version as well.

The capture to disk is always correct by the way, with the full length capture, no matter if this bug happens or not.

Also, is it intended for 900 seconds to be the maximum delay possible? Any setting of 901 seconds or more isn't accepted.

17:57:05: Open Broadcaster Software v0.541b - 32bit (´・ω・｀)
17:57:05: -------------------------------
17:57:05: CPU Name: Intel(R) Core(TM) i7-2600K CPU @ 3.40GHz
17:57:05: CPU Speed: 3400MHz
17:57:05: Physical Memory:  4095MB Total, 4095MB Free
17:57:05: stepping id: 7, model 10, family 6, type 0, extmodel 1, extfamily 0, HTT 1, logical cores 8, total cores 4
17:57:05: monitor 1: pos={0, 0}, size={1680, 1050}
17:57:05: Windows Version: 6.1 Build 7601 S
17:57:05: Aero is Disabled
17:57:05: -------------------------------
17:57:05: OBS Modules:
17:57:05: Base Address     Module
17:57:05: 00E70000         OBS.exe
17:57:05: 73970000         OBSApi.dll
17:57:05: 73290000         DShowPlugin.dll
17:57:05: 73270000         GraphicsCapture.dll
17:57:05: 73250000         NoiseGate.dll
17:57:05: 73230000         PSVPlugin.dll
17:57:05: ------------------------------------------
17:57:05: Adapter 1
17:57:05:   Video Adapter: NVIDIA GeForce GTX 560 Ti  
17:57:05:   Video Adapter Dedicated Video Memory: 1025966080
17:57:05:   Video Adapter Shared System Memory: 3220779008
17:57:05: =====Stream Start: 2013-07-13, 17:57:05===============================================
17:57:05:   Multithreaded optimizations: On
17:57:05:   Base resolution: 1920x1080
17:57:05:   Output resolution: 1280x720
17:57:05: ------------------------------------------
17:57:05: Loading up D3D10...
17:57:05: Playback device Default
17:57:05: ------------------------------------------
17:57:05: Using desktop audio input: Speakers (Creative SB X-Fi)
17:57:05: ------------------------------------------
17:57:05: Using auxilary audio input: Microphone (3- USB Audio Device)
17:57:05: ------------------------------------------
17:57:05: Audio Encoding: AAC
17:57:05:     bitrate: 160
17:57:05: ------------------------------------------
17:57:05:     device: AVerMedia HD Capture C985 Bus 4,
17:57:05:     device id \\?\pci#ven_1af2&dev_a001&subsys_a0011af2&rev_00#4&1d7623a1&0&00e2#{65e8773d-8f56-11d0-a3b9-00a0c9223196}\{957bd672-7934-4b55-b81a-3e22b14c679a},
17:57:05:     chosen type: YV12, usingFourCC: true, res: 1920x1080 - 1920x1080, frameIntervals: 333333-666666, fourCC: 'YV12'
17:57:05:     audio device: Disable,
17:57:05:     audio device id Disabled,
17:57:05: 
17:57:06: Using directshow input
17:57:06: Using custom x264 settings: "opencl=true threads=10"
17:57:08: ------------------------------------------
17:57:08: Video Encoding: x264
17:57:08:     fps: 30
17:57:08:     width: 1280, height: 720
17:57:08:     preset: medium
17:57:08:     CBR: yes
17:57:08:     CFR: yes
17:57:08:     max bitrate: 3000
17:57:08: ------------------------------------------
18:12:11: Using RTMP service: Twitch / Justin.tv
18:12:11:   Server selection: rtmp://live-iad.justin.tv/app
18:12:14: SO_SNDBUF was at 8192
18:12:14: SO_SNDBUF is now 65536
21:32:30: Total frames rendered: 387659, number of frames that lagged: 40 (0.01%) (it's okay for some frames to lag)
21:32:30: Total duplicated frames: 8 (0.00%)
21:32:43: RTMPPublisher::SocketLoop: Socket error, send() returned -1, GetLastError() 10053
21:32:44: librtmp error: WriteN, RTMP send error 10053 (79 bytes)
21:32:44: librtmp error: WriteN, RTMP send error 10038 (42 bytes)
21:32:44: Number of times waited to send: 0, Waited for a total of 0 bytes
21:32:44: Number of b-frames dropped: 0 (0%), Number of p-frames dropped: 0 (0%), Total 0 (0%)
21:32:44: =====Stream End: 2013-07-13, 21:32:44=================================================
21:33:59: 
21:33:59: Profiler results:
21:33:59: 
21:33:59: ==============================================================
21:33:59: frame - [100%] [avg time: 3.845 ms (cpu time: avg 3.671 ms, total 1.4233e+006 ms)] [avg calls per frame: 1] [children: 88.2%] [unaccounted: 11.8%]
21:33:59: | scene->Preprocess - [24.7%] [avg time: 0.949 ms (cpu time: avg 0.922 ms, total 357547 ms)] [avg calls per frame: 1]
21:33:59: | video encoding and uploading - [63.5%] [avg time: 2.441 ms (cpu time: avg 2.386 ms, total 925078 ms)] [avg calls per frame: 1] [children: 62.2%] [unaccounted: 1.25%]
21:33:59: | | CopyResource - [0.494%] [avg time: 0.019 ms (cpu time: avg 0.018 ms, total 7156.25 ms)] [avg calls per frame: 0]
21:33:59: | | conversion to 4:2:0 - [0.156%] [avg time: 0.006 ms (cpu time: avg 0.005 ms, total 2015.63 ms)] [avg calls per frame: 0]
21:33:59: | | call to encoder - [43.3%] [avg time: 1.664 ms (cpu time: avg 1.625 ms, total 630141 ms)] [avg calls per frame: 0]
21:33:59: | | sending stuff out - [18.3%] [avg time: 0.704 ms (cpu time: avg 0.707 ms, total 274188 ms)] [avg calls per frame: 0]
21:33:59: | Convert444Threads - [1.73e+003%] [avg time: 66.663 ms (cpu time: avg 1.987 ms, total 770500 ms)] [avg calls per frame: 1]
21:33:59: ==============================================================
21:33:59:

 

[Lain]

Re: Stream ends immediately instead of finishing delayed str

If you get disconnected while streaming a delayed stream, it will cut off your delay, there's pretty much nothing you can do about it currently. I do not recommend delaying your stream unless you actually know your connection is reliable. Make sure you have the best server and have done testing on that server to ensure it won't disconnect. But even then you cannot guarantee against disconnects. Disconnections can happen for any variety of reasons and there's not much else you can do except for ensure you have the best possible server and the most reliable connection possible.

That all having been said: Why in gods name are you delaying by 15 minutes? For stream cheating, I can understand like 2-3 minutes, but 15 minutes? What the heck are you playing, world of tanks or something where you're constantly camped in hidden positions? 15 minutes is the max because if you need it for more you're just asking for trouble (such as the trouble you're experiencing)

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

Thanks for the response. But it seems like you're focusing on the disconnection part, which is a symptom, not a cause.

I'm not getting disconnected, OBS is ending the stream early. It gives me the disconnection notice when I click "end stream", at which point it should continue the cached stream for another 15 minutes, but often doesn't. I'm not actually experiencing a disrupted connection. It is clearly a problem with OBS, not an internet issue.

I'm playing Planetside 2, an MMOFPS. It can take over 15 minutes to attack and capture a single base, a "stream cheater" could, among other things, see where my faction parked our respawn vehicles and more easily destroy them just by knowing their locations. That's why I maximize the delay.

 

[Kharay]

Re: Stream ends immediately instead of finishing delayed str

I would have to guess that even though 15 minutes is available, it is simply not stable. It seems like an excessive delay, both on a software level as well as on a practical level. What I mean is -- I don't think it's ever going to work as well as one would expect, that long of a delay. Too bad it takes so long for it to bug out on you though, I'd be willing to experiment a bit with it otherwise.

Regardless of that fact -- I can understand the particular issue regarding Planetside 2 but is it really necessary to go with that long of a delay? I mean, I'd imagine 5 minutes would give you ample time to respond even if you are being stream sniped. It would still give you a 5 minute head start. Just offering this point of view as a possible workaround until such a time that this can be resolved. Assuming it is OBS that is causing it.

 

[Lain]

Re: Stream ends immediately instead of finishing delayed str

Ah okay, then my apologies, admittedly streams with that high of a delay haven't been tested. 10053 is a disconnection from server though. Does it try to finish the transmission and fail partway or something? The server is definitely disconnecting you in the log

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

I suspect it may be related to whatever OBS does right when it finishes recording a stream to the hard drive. Saves from a temp to a permanent file? There used to be a dialog box but that went away in a recent update. Anyways, when the recording is short, whatever OBS does when ending a recording to the hard drive takes a short amount of time, and it succeeds. It takes a longer amount of time when the recorded file is longer, and then it fails.

21:32:43: RTMPPublisher::SocketLoop: Socket error, send() returned -1, GetLastError() 10053
21:32:44: librtmp error: WriteN, RTMP send error 10053 (79 bytes)

So what you're saying is that the Twitch server is disconnecting me at this point? I suspect when its doing this file copy or append or whatever, OBS stops sending until it finishes its file operation, and if it takes too long, gets disconnected by Twitch, given what you said above.

 

[Lain]

Re: Stream ends immediately instead of finishing delayed str

Ah okay, then this is because of file output. I'll check out the code and see if I can fix it.

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

Ah okay, then this is because of file output. I'll check out the code and see if I can fix it.

Great, thanks!

 

[FerretBomb]

Re: Stream ends immediately instead of finishing delayed str

Just to add my two cents, I've noticed similar with no delay; if I immediately hit the 'Stop Streaming' button when my outro music completes, I'll lose between 3-5 seconds of the end of my cast for active watchers, and on the VOD.
I have no delay set, and it's minor, but it's still a possibly-related bug.

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

I just did another long stream with a 150 second delay instead of 900 second, and the same thing occurred. I think this isn't related to the length of the delay, just that there is a long stream and that it doesn't continue to stream while its writing to the hard drive, and when that happens Twitch thinks the stream has ended and disconnects.

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

This bug happened again with a 30 second delay. I conclude that the amount of delay doesn't matter, other than when the delay is very small, people tend to not even notice, because there's nothing left cached to send.

 

[Lain]

Re: Stream ends immediately instead of finishing delayed str

The bug as described in the original post is (hopefully) fixed in the latest source code and will be uploaded in a patch soon

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

The bug as described in the original post is (hopefully) fixed in the latest source code and will be uploaded in a patch soon

Awesome, thanks.

Just as a side note, I've been testing different configurations. The one last night was interesting. I decided to save the capture to disk to the SSD on the install drive instead of the large storage volume that I normally save to. This lessens the time it takes to save the file, so that the connection to Twitch doesn't time out. What is interesting is that I was again using a 900 second delay, and when I ended the stream, it seemed to work, it kept streaming the delayed stream. For 12 minutes, then it ended it ~ 3 minutes early. No reconnection attempt afterwards. So the last 3 minutes never got sent to Twitch.

 

[Kharay]

Re: Stream ends immediately instead of finishing delayed str

This is interesting to note as well.

 

[Boildown]

Re: Stream ends immediately instead of finishing delayed str

The bug as described in the original post is (hopefully) fixed in the latest source code and will be uploaded in a patch soon

Autoupdated to .542b today, streamed with 900 second delay, and it worked correctly after a 2.5 hour session saving to my normal platter hard drive, not the SSD. It also didn't cut off the delayed stream early like I described in my last post. So this may well be fixed, thanks! When I get a chance to stream over 3 hours then that will be the definitive test, but for now it looks good.