Unable to make CasparCG Server 2.2 work

Hey all,

sorry for probably a stupid question, but I am having really hard time making CasparCG 2.2 (current master) work.
I have a setup with stable 2.0.7 version running quite fine for several months with a modified version of this client https://github.com/baltedewit/folderplayout.
Currently, I am trying to update my setup to current master release, because I hope newer ffmpeg could solve some of my streaming issues (Invalidated TLS for instance). But after a several day struggle I am unable to make caspar play anything.
Could someone please direct me to some instructions on how to debug the issue. So far, I am not very enlightened by the error messages (attached).

Thank you for any feedback.

CasparCG log:
https://pastebin.com/raw/qMNVLa1g

Looks like an issue in the CasparCG-connection library that client is using. You could try upgrading that, since it is running a release that is 1,5 years old.

Thank you very much for your suggestion. I tried updating the package, but there is no change as I can see.

New log:
[2018-08-01 18:34:00.136] [debug] Executing command: LOADBG
[2018-08-01 18:34:00.137] [info] Received message from 127.0.0.1: REQ cbxjcn2 PLAY 1-20\r\n
[2018-08-01 18:34:00.138] [error] Turn on log level debug for stacktrace.
[2018-08-01 18:34:00.138] [info] Sent message to 127.0.0.1:RES pby3c7n 404 LOADBG FAILED\r\n
[2018-08-01 18:34:00.138] [debug] Executing command: PLAY
[2018-08-01 18:34:00.138] [debug] Executed command (0s): PLAY
[2018-08-01 18:34:00.138] [info] Sent message to 127.0.0.1:RES cbxjcn2 202 PLAY OK\r\n
[2018-08-01 18:34:00.138] [info] Received message from 127.0.0.1: REQ o4unqyo LOADBG 1-20 “The Expanse - S03E02.mkv”\r\n
[2018-08-01 18:34:00.138] [debug] Executing command: LOADBG
[2018-08-01 18:34:00.140] [error] Turn on log level debug for stacktrace.
[2018-08-01 18:34:00.140] [info] Sent message to 127.0.0.1:RES o4unqyo 404 LOADBG FAILED\r\n
[2018-08-01 18:34:10.143] [info] Received message from 127.0.0.1: REQ tjai2m8 PLAY 1-20\r\n
[2018-08-01 18:34:10.143] [debug] Executing command: PLAY
[2018-08-01 18:34:10.143] [debug] Executed command (0s): PLAY
[2018-08-01 18:34:10.143] [info] Sent message to 127.0.0.1:RES tjai2m8 202 PLAY OK\r\n

Ah, I see now. Looks like you are sending the file name with extension. CasparCG 2.2.0 does not allow for that.

Again, thank you, but still no luck here.

[2018-08-01 19:58:37.963] [info] async_event_server[:5250] Accepted connection from 127.0.0.1 (1 connections).
[2018-08-01 19:58:37.969] [info] Received message from 127.0.0.1: REQ nlb4aon CLEAR 1\r\n
[2018-08-01 19:58:37.969] [debug] Executing command: CLEAR
[2018-08-01 19:58:37.969] [debug] Executed command (0s): CLEAR
[2018-08-01 19:58:37.969] [info] Sent message to 127.0.0.1:RES nlb4aon 202 CLEAR OK\r\n
[2018-08-01 19:59:00.046] [info] Received message from 127.0.0.1: REQ uo4u02t STOP 1-20\r\n
[2018-08-01 19:59:00.046] [debug] Executing command: STOP
[2018-08-01 19:59:00.047] [debug] Executed command (0.001s): STOP
[2018-08-01 19:59:00.047] [info] Sent message to 127.0.0.1:RES uo4u02t 202 STOP OK\r\n
[2018-08-01 19:59:00.047] [info] Received message from 127.0.0.1: REQ xav1sb8 STOP 1-1\r\n
[2018-08-01 19:59:00.048] [debug] Executing command: STOP
[2018-08-01 19:59:00.048] [debug] Executed command (0s): STOP
[2018-08-01 19:59:00.048] [info] Sent message to 127.0.0.1:RES xav1sb8 202 STOP OK\r\n
[2018-08-01 19:59:00.049] [info] Received message from 127.0.0.1: REQ 341mymm CLEAR 1-20\r\n
[2018-08-01 19:59:00.049] [debug] Executing command: CLEAR
[2018-08-01 19:59:00.049] [debug] Executed command (0s): CLEAR
[2018-08-01 19:59:00.050] [info] Sent message to 127.0.0.1:RES 341mymm 202 CLEAR OK\r\n
[2018-08-01 19:59:00.067] [info] Received message from 127.0.0.1: REQ s3o5jeu PLAY 1-20 “logo/B01/logo.tga”\r\n
[2018-08-01 19:59:00.067] [debug] Executing command: PLAY
[2018-08-01 19:59:00.071] [error] Turn on log level debug for stacktrace.
[2018-08-01 19:59:00.071] [info] Sent message to 127.0.0.1:RES s3o5jeu 404 PLAY FAILED\r\n
[2018-08-01 19:59:00.072] [info] Received message from 127.0.0.1: REQ 62lo4w2 LOADBG 1-20 “The Expanse - S03E01”\r\n
[2018-08-01 19:59:00.073] [debug] Executing command: LOADBG
[2018-08-01 19:59:00.076] [debug] Executed command (0.003s): LOADBG
[2018-08-01 19:59:00.076] [info] Sent message to 127.0.0.1:RES 62lo4w2 202 LOADBG OK\r\n
[2018-08-01 19:59:00.077] [debug] [ffmpeg] [h264 @ 00000286061A86C0] Reinit context to 1920x1088, pix_fmt: yuv420p
[2018-08-01 19:59:00.077] [debug]
[2018-08-01 19:59:00.080] [info] Received message from 127.0.0.1: REQ c0gpmlm PLAY 1-20\r\n
[2018-08-01 19:59:00.080] [debug] Executing command: PLAY
[2018-08-01 19:59:00.080] [debug] Executed command (0s): PLAY
[2018-08-01 19:59:00.080] [info] Sent message to 127.0.0.1:RES c0gpmlm 202 PLAY OK\r\n
[2018-08-01 19:59:00.086] [info] Received message from 127.0.0.1: REQ 3ck8rwo LOADBG 1-20 “The Expanse - S03E02”\r\n
[2018-08-01 19:59:00.086] [debug] Executing command: LOADBG
[2018-08-01 19:59:00.086] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028605DAA8C0] fps=50/1
[2018-08-01 19:59:00.086] [debug]
[2018-08-01 19:59:00.086] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028605DAA8C0] 0 frames in, 0 frames out; 0 frames dropped, 0 frames duplicated.
[2018-08-01 19:59:00.086] [debug]
[2018-08-01 19:59:00.087] [debug] [ffmpeg] [Parsed_fps_2 @ 00000286061AEEC0] fps=50/1
[2018-08-01 19:59:00.087] [debug]
[2018-08-01 19:59:00.088] [debug] [ffmpeg] [in_0 @ 00000286061AC2C0] w:1920 h:1080 pixfmt:yuv420p tb:1/1000 fr:24000/1001 sar:1/1 sws_param:
[2018-08-01 19:59:00.088] [debug]
[2018-08-01 19:59:00.088] [debug] [ffmpeg] [Parsed_fps_2 @ 00000286061AEEC0] Set first pts to (in:0 out:0) from start time 0.000000
[2018-08-01 19:59:00.088] [debug]
[2018-08-01 19:59:00.089] [debug] [ffmpeg] [h264 @ 00000286061ACBC0] Reinit context to 1920x1088, pix_fmt: yuv420p
[2018-08-01 19:59:00.089] [debug]
[2018-08-01 19:59:00.089] [debug] Executed command (0.003s): LOADBG
[2018-08-01 19:59:00.089] [info] Sent message to 127.0.0.1:RES 3ck8rwo 202 LOADBG OK\r\n
[2018-08-01 19:59:00.089] [debug] [ffmpeg] [Parsed_asetnsamples_3 @ 0000028610054C80] nb_out_samples:1024 pad:0
[2018-08-01 19:59:00.089] [debug]
[2018-08-01 19:59:00.090] [debug] [ffmpeg] [Parsed_asetnsamples_3 @ 0000028610055480] nb_out_samples:1024 pad:0
[2018-08-01 19:59:00.090] [debug]
[2018-08-01 19:59:00.091] [debug] [ffmpeg] [in_1 @ 0000028610055280] tb:1/1000 samplefmt:fltp samplerate:48000 chlayout:0x3f
[2018-08-01 19:59:00.091] [debug]
[2018-08-01 19:59:00.091] [debug] [ffmpeg] [Parsed_aresample_1 @ 0000028610054A80] ch:6 chl:5.1 fmt:fltp r:48000Hz -> ch:6 chl:5.1 fmt:s32 r:48000Hz
[2018-08-01 19:59:00.091] [debug]
[2018-08-01 19:59:00.097] [debug] [ffmpeg] [h264 @ 00000286100AC040] Reinit context to 1920x1088, pix_fmt: yuv420p
[2018-08-01 19:59:00.097] [debug]
[2018-08-01 19:59:00.097] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028610054D80] fps=50/1
[2018-08-01 19:59:00.097] [debug]
[2018-08-01 19:59:00.098] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028610054D80] 0 frames in, 0 frames out; 0 frames dropped, 0 frames duplicated.
[2018-08-01 19:59:00.098] [debug]
[2018-08-01 19:59:00.098] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028610054880] fps=50/1
[2018-08-01 19:59:00.098] [debug]
[2018-08-01 19:59:00.099] [debug] [ffmpeg] [in_0 @ 0000028610055C80] w:1920 h:1080 pixfmt:yuv420p tb:1/1000 fr:24000/1001 sar:1/1 sws_param:
[2018-08-01 19:59:00.099] [debug]
[2018-08-01 19:59:00.100] [debug] [ffmpeg] [Parsed_fps_2 @ 0000028610054880] Set first pts to (in:0 out:0) from start time 0.000000
[2018-08-01 19:59:00.100] [debug]
[2018-08-01 19:59:00.100] [debug] [ffmpeg] [Parsed_asetnsamples_3 @ 0000028610054F80] nb_out_samples:1024 pad:0
[2018-08-01 19:59:00.100] [debug]
[2018-08-01 19:59:00.101] [debug] [ffmpeg] [Parsed_asetnsamples_3 @ 0000028610055B80] nb_out_samples:1024 pad:0
[2018-08-01 19:59:00.101] [debug]
[2018-08-01 19:59:00.101] [debug] [ffmpeg] [in_1 @ 0000028610055D80] tb:1/1000 samplefmt:fltp samplerate:48000 chlayout:0x3f
[2018-08-01 19:59:00.101] [debug]
[2018-08-01 19:59:00.101] [debug] [ffmpeg] [Parsed_aresample_1 @ 0000028610054980] ch:6 chl:5.1 fmt:fltp r:48000Hz -> ch:6 chl:5.1 fmt:s32 r:48000Hz
[2018-08-01 19:59:00.101] [debug]
[2018-08-01 19:59:00.101] [debug] [ffmpeg] [h264 @ 00000286100A9B40] Reinit context to 1920x1088, pix_fmt: yuv420p
[2018-08-01 19:59:00.101] [debug]
[2018-08-01 19:59:00.105] [error] [ffmpeg] [in_1 @ 0000028610055280] Changing frame properties on the fly is not supported.
[2018-08-01 19:59:00.105] [error]
[2018-08-01 19:59:00.105] [error] [ffmpeg] [in_1 @ 0000028610055280] Changing frame properties on the fly is not supported.
[2018-08-01 19:59:00.105] [error]
[2018-08-01 19:59:00.109] [error] [ffmpeg] [in_1 @ 0000028610055D80] Changing frame properties on the fly is not supported.
[2018-08-01 19:59:00.109] [error]
[2018-08-01 19:59:00.109] [error] [ffmpeg] [in_1 @ 0000028610055D80] Changing frame properties on the fly is not supported.
[2018-08-01 19:59:00.109] [error]
[2018-08-01 19:59:00.105] [error] Exception: C:\Program Files (x86)\Jenkins\workspace\casparcg-server-dep\master\src\modules\ffmpeg\producer\av_producer.cpp(836): Throw in function bool _cdecl caspar::ffmpeg::AVProducer::Impl::schedule(void)
[2018-08-01 19:59:00.105] [error] Dynamic exception type: class boost::exception_detail::clone_impl
[2018-08-01 19:59:00.105] [error] [struct boost::errinfo_api_function
* _ptr64] = av_buffersrc_write_frame(source, frame.get())
[2018-08-01 19:59:00.105] [error] [struct boost::errinfo_errno
* __ptr64] = 22, “Invalid argument”
[2018-08-01 19:59:00.105] [error] [struct caspar::tag_stacktrace_info * __ptr64] = 0# 0x00007FF7565E97BE in casparcg
[2018-08-01 19:59:00.105] [error] 1# 0x00007FF756618B60 in casparcg
[2018-08-01 19:59:00.105] [error] 2# 0x00007FF7567E9FAC in casparcg
[2018-08-01 19:59:00.105] [error] 3# 0x00007FF7567E3C1F in casparcg
[2018-08-01 19:59:00.105] [error] 4# 0x00007FF756960DE3 in casparcg
[2018-08-01 19:59:00.105] [error] 5# o_strcat_s in ucrtbase
[2018-08-01 19:59:00.105] [error] 6# BaseThreadInitThunk in KERNEL32
[2018-08-01 19:59:00.105] [error] 7# RtlUserThreadStart in ntdll
[2018-08-01 19:59:00.105] [error]
[2018-08-01 19:59:00.105] [error]

[2018-08-01 19:59:00.105] [error] 0# 0x00007FF7565E97BE in casparcg
[2018-08-01 19:59:00.105] [error] 1# 0x00007FF7565E90EF in casparcg
[2018-08-01 19:59:00.105] [error] 2# 0x00007FF756B026EA in casparcg
[2018-08-01 19:59:00.105] [error] 3# _C_specific_handler in VCRUNTIME140
[2018-08-01 19:59:00.105] [error] 4# _TypeMatch in VCRUNTIME140
[2018-08-01 19:59:00.105] [error] 5# RtlCaptureContext in ntdll
[2018-08-01 19:59:00.105] [error] 6# 0x00007FF7567E3C1F in casparcg
[2018-08-01 19:59:00.105] [error] 7# 0x00007FF756960DE3 in casparcg
[2018-08-01 19:59:00.105] [error] 8# o_strcat_s in ucrtbase
[2018-08-01 19:59:00.105] [error] 9# BaseThreadInitThunk in KERNEL32
[2018-08-01 19:59:00.105] [error] 10# RtlUserThreadStart in ntdll
[2018-08-01 19:59:00.105] [error]
[2018-08-01 19:59:00.109] [error] Exception: C:\Program Files (x86)\Jenkins\workspace\casparcg-server-dep\master\src\modules\ffmpeg\producer\av_producer.cpp(836): Throw in function bool _cdecl caspar::ffmpeg::AVProducer::Impl::schedule(void)
[2018-08-01 19:59:00.109] [error] Dynamic exception type: class boost::exception_detail::clone_impl
[2018-08-01 19:59:00.109] [error] [struct boost::errinfo_api_function
* _ptr64] = av_buffersrc_write_frame(source, frame.get())
[2018-08-01 19:59:00.109] [error] [struct boost::errinfo_errno
* __ptr64] = 22, “Invalid argument”
[2018-08-01 19:59:00.109] [error] [struct caspar::tag_stacktrace_info * __ptr64] = 0# 0x00007FF7565E97BE in casparcg
[2018-08-01 19:59:00.109] [error] 1# 0x00007FF756618B60 in casparcg
[2018-08-01 19:59:00.109] [error] 2# 0x00007FF7567E9FAC in casparcg
[2018-08-01 19:59:00.109] [error] 3# 0x00007FF7567E3C1F in casparcg
[2018-08-01 19:59:00.109] [error] 4# 0x00007FF756960DE3 in casparcg
[2018-08-01 19:59:00.109] [error] 5# o_strcat_s in ucrtbase
[2018-08-01 19:59:00.109] [error] 6# BaseThreadInitThunk in KERNEL32
[2018-08-01 19:59:00.109] [error] 7# RtlUserThreadStart in ntdll
[2018-08-01 19:59:00.109] [error]
[2018-08-01 19:59:00.109] [error]

[2018-08-01 19:59:00.109] [error] 0# 0x00007FF7565E97BE in casparcg
[2018-08-01 19:59:00.109] [error] 1# 0x00007FF7565E90EF in casparcg
[2018-08-01 19:59:00.109] [error] 2# 0x00007FF756B026EA in casparcg
[2018-08-01 19:59:00.109] [error] 3# _C_specific_handler in VCRUNTIME140
[2018-08-01 19:59:00.109] [error] 4# _TypeMatch in VCRUNTIME140
[2018-08-01 19:59:00.109] [error] 5# RtlCaptureContext in ntdll
[2018-08-01 19:59:00.109] [error] 6# 0x00007FF7567E3C1F in casparcg
[2018-08-01 19:59:00.109] [error] 7# 0x00007FF756960DE3 in casparcg
[2018-08-01 19:59:00.109] [error] 8# o_strcat_s in ucrtbase
[2018-08-01 19:59:00.109] [error] 9# BaseThreadInitThunk in KERNEL32
[2018-08-01 19:59:00.109] [error] 10# RtlUserThreadStart in ntdll
[2018-08-01 19:59:00.109] [error]
[2018-08-01 19:59:10.096] [info] Received message from 127.0.0.1: REQ osdkn85 PLAY 1-20\r\n
[2018-08-01 19:59:10.096] [debug] Executing command: PLAY
[2018-08-01 19:59:10.096] [debug] Executed command (0s): PLAY
[2018-08-01 19:59:10.096] [info] Sent message to 127.0.0.1:RES osdkn85 202 PLAY OK\r\n

Okay, that looks like in issue in CasparCG Server. Please try with the latest 2.2 from http://builds.casparcg.com/ and if that doesn’t work then please open an issue on https://github.com/casparcg/server