ValveSoftware
The new media source in experimental fails to play any video
I build Wine regularly using the TkG build system and I've noticed an issue with video playback that started around July 5 when the new media source was pushed to the experimental branch (I couldn't bisect it to the exact commit, most intermediate commits fail to compile).
Every game I tested with the current experimental branch that uses mfplat for videos fails to display them: the audio plays but the video is either completely white, gray or black. This happens both with and without hardware decoding.
Enabling gstreamer debug output, I get the following log when it tries to play a video:
0:00:00.140566985 5785 0x75109c011560 INFO GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "bin"
0:00:00.140590765 5785 0x75109c011560 LOG WINE wg_allocator.c:157:wg_allocator_init: allocator 0x75109c450ea0
0:00:00.140598975 5785 0x75109c011560 TRACE WINE wg_media_type.c:404:caps_from_video_format: subtype {34363248-0000-0010-8000-00aa00389b71} 0x0, FPS 0:0, aperture (0,0)-(0,0), PAR 0:0, videoFlags 0.
0:00:00.140602445 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: ---------------------------------------------------------------------------
0:00:00.140605135 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: extra bytes:
0:00:00.140608885 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: 00000000: 00 00 00 01 67 4d 40 34 95 90 03 c0 04 3e c0 44 ....gM@4.....>.D
0:00:00.140612165 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: 00000010: 00 00 0f a0 00 07 53 02 10 00 00 00 01 68 eb 8f ......S......h..
0:00:00.140614605 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: 00000020: 20
0:00:00.140616645 5785 0x75109c011560 MEMDUMP WINE wg_media_type.c:409:caps_from_video_format: ---------------------------------------------------------------------------
0:00:00.140634805 5785 0x75109c011560 TRACE WINE wg_media_type.c:454:caps_from_media_type: caps video/x-h264, codec_data=(buffer)00000001674d4034959003c0043ec04400000fa000075302100000000168eb8f20, stream-format=(string)byte-stream, alignment=(string)au
0:00:00.140639805 5785 0x75109c011560 INFO WINE wg_transform.c:553:wg_transform_create: transform 0x75109c450420 input caps video/x-h264, codec_data=(buffer)00000001674d4034959003c0043ec04400000fa000075302100000000168eb8f20, stream-format=(string)byte-stream, alignment=(string)au
0:00:00.140645455 5785 0x75109c011560 TRACE WINE wg_media_type.c:404:caps_from_video_format: subtype {3231564e-0000-0010-8000-00aa00389b71} 1920x1080, FPS 30000:1001, aperture (0,0)-(1920,1080), PAR 1:1, videoFlags 0.
0:00:00.140654825 5785 0x75109c011560 TRACE WINE wg_media_type.c:454:caps_from_media_type: caps video/x-raw, format=(string)NV12, width=(int)1920, height=(int)1080, pixel-aspect-ratio=(fraction)1/1, framerate=(fraction)30000/1001
0:00:00.140658635 5785 0x75109c011560 INFO WINE wg_transform.c:558:wg_transform_create: transform 0x75109c450420 output caps video/x-raw, format=(string)NV12, width=(int)1920, height=(int)1080, pixel-aspect-ratio=(fraction)1/1, framerate=(fraction)30000/1001
0:00:00.140661415 5785 0x75109c011560 LOG WINE unix_private.h:133:touch_h264_used_tag: h264 is used
0:00:00.140663525 5785 0x75109c011560 WARN WINE unix_private.h:155:touch_h264_used_tag: STEAM_COMPAT_SHADER_PATH not set, cannot create h264-used file
0:00:00.141097235 5785 0x75109c011560 INFO GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "h264parse"
0:00:00.141106796 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x75109c452b50> adding pad 'sink'
0:00:00.141111416 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x75109c452b50> adding pad 'src'
0:00:00.141117106 5785 0x75109c011560 INFO baseparse gstbaseparse.c:4067:gst_base_parse_set_pts_interpolation:<GstH264Parse@0x75109c452b50> PTS interpolation: no
0:00:00.141119576 5785 0x75109c011560 INFO baseparse gstbaseparse.c:4085:gst_base_parse_set_infer_ts:<GstH264Parse@0x75109c452b50> TS inferring: no
0:00:00.141124496 5785 0x75109c011560 INFO WINE unixlib.c:88:factory_create_element: Created element <h264parse1> from factory <h264parse>.
0:00:00.141136096 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to NULL
0:00:00.141139056 5785 0x75109c011560 DEBUG WINE unixlib.c:182:append_element: Linked h264parse1 element 0x75109c452b50.
0:00:00.141433556 5785 0x75109c011560 INFO GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "avdec_h264"
0:00:00.141446256 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstVideoDecoder@0x75109c456250> adding pad 'sink'
0:00:00.141450086 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstVideoDecoder@0x75109c456250> adding pad 'src'
0:00:00.141456956 5785 0x75109c011560 INFO WINE unixlib.c:88:factory_create_element: Created element <avdec_h264-1> from factory <avdec_h264>.
0:00:00.141462416 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<avdec_h264-1> completed state change to NULL
0:00:00.141466106 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element h264parse1:(any) to element avdec_h264-1:(any)
0:00:00.141470586 5785 0x75109c011560 INFO GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link h264parse1:src and avdec_h264-1:sink
0:00:00.141478596 5785 0x75109c011560 INFO GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_h264-1:src> pad has no peer
0:00:00.141492236 5785 0x75109c011560 INFO GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: h264parse1 and avdec_h264-1 in same bin, no need for ghost pads
0:00:00.141497766 5785 0x75109c011560 INFO GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link h264parse1:src and avdec_h264-1:sink
0:00:00.141501496 5785 0x75109c011560 INFO GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_h264-1:src> pad has no peer
0:00:00.141508966 5785 0x75109c011560 INFO GST_PADS gstpad.c:2621:gst_pad_link_full: linked h264parse1:src and avdec_h264-1:sink, successful
0:00:00.141511306 5785 0x75109c011560 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.141514446 5785 0x75109c011560 INFO GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<h264parse1:src> Received event on flushing pad. Discarding
0:00:00.141518866 5785 0x75109c011560 DEBUG WINE unixlib.c:182:append_element: Linked avdec_h264-1 element 0x75109c456250.
0:00:00.141522436 5785 0x75109c011560 DEBUG WINE unixlib.c:388:set_max_threads: avdec_h264 found, setting max-threads to 16.
0:00:00.141526716 5785 0x75109c011560 INFO GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "videoconvert"
0:00:00.141532816 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x75109c459d90> adding pad 'sink'
0:00:00.141537046 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x75109c459d90> adding pad 'src'
0:00:00.141545576 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert1> completed state change to NULL
0:00:00.141548556 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element avdec_h264-1:(any) to element videoconvert1:(any)
0:00:00.141551616 5785 0x75109c011560 INFO GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link avdec_h264-1:src and videoconvert1:sink
0:00:00.141555836 5785 0x75109c011560 INFO GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert1:src> pad has no peer
0:00:00.141877366 5785 0x75109c011560 INFO GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: avdec_h264-1 and videoconvert1 in same bin, no need for ghost pads
0:00:00.141882536 5785 0x75109c011560 INFO GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link avdec_h264-1:src and videoconvert1:sink
0:00:00.141886406 5785 0x75109c011560 INFO GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert1:src> pad has no peer
0:00:00.142186096 5785 0x75109c011560 INFO GST_PADS gstpad.c:2621:gst_pad_link_full: linked avdec_h264-1:src and videoconvert1:sink, successful
0:00:00.142188406 5785 0x75109c011560 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.142191176 5785 0x75109c011560 INFO GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<avdec_h264-1:src> Received event on flushing pad. Discarding
0:00:00.142196116 5785 0x75109c011560 DEBUG WINE unixlib.c:182:append_element: Linked videoconvert1 element 0x75109c459d90.
0:00:00.142202306 5785 0x75109c011560 INFO GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link '':src and h264parse1:sink
0:00:00.142204816 5785 0x75109c011560 INFO GST_PADS gstutils.c:1104:gst_pad_check_link: Src pad '':src has no parent, failed
0:00:00.142210466 5785 0x75109c011560 TRACE WINE wg_transform.c:296:transform_src_query_cb: transform 0x75109c450420, ignoring caps query: 0x75109c457e70, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL";
0:00:00.142217066 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad h264parse1:sink
0:00:00.142220966 5785 0x75109c011560 INFO GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link '':src and h264parse1:sink
0:00:00.142224446 5785 0x75109c011560 TRACE WINE wg_transform.c:296:transform_src_query_cb: transform 0x75109c450420, ignoring caps query: 0x75109c457e70, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL";
0:00:00.142228986 5785 0x75109c011560 INFO GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert1:src> pad has no peer
0:00:00.142853977 5785 0x75109c011560 INFO GST_PADS gstpad.c:2621:gst_pad_link_full: linked '':src and h264parse1:sink, successful
0:00:00.142858437 5785 0x75109c011560 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.142861537 5785 0x75109c011560 INFO GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<'':src> Received event on flushing pad. Discarding
0:00:00.142865337 5785 0x75109c011560 INFO GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link videoconvert1:src and '':sink
0:00:00.142867867 5785 0x75109c011560 INFO GST_PADS gstutils.c:1109:gst_pad_check_link: Sink pad videoconvert1:src has no parent, failed
0:00:00.142872227 5785 0x75109c011560 LOG WINE wg_transform.c:387:transform_sink_query_caps: transform 0x75109c450420, caps query: 0x75109c458b50, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL";
0:00:00.142877637 5785 0x75109c011560 INFO WINE wg_transform.c:403:transform_sink_query_caps: Returning caps video/x-raw, format=(string)NV12, width=(int)1920, height=(int)1080
0:00:00.142886257 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad videoconvert1:src
0:00:00.142890967 5785 0x75109c011560 INFO GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link videoconvert1:src and '':sink
0:00:00.143357917 5785 0x75109c011560 LOG WINE wg_transform.c:387:transform_sink_query_caps: transform 0x75109c450420, caps query: 0x75109c458b50, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL";
0:00:00.143363167 5785 0x75109c011560 INFO WINE wg_transform.c:403:transform_sink_query_caps: Returning caps video/x-raw, format=(string)NV12, width=(int)1920, height=(int)1080
0:00:00.143373667 5785 0x75109c011560 INFO GST_PADS gstpad.c:2621:gst_pad_link_full: linked videoconvert1:src and '':sink, successful
0:00:00.143375667 5785 0x75109c011560 INFO GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.143378097 5785 0x75109c011560 INFO GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<videoconvert1:src> Received event on flushing pad. Discarding
0:00:00.143388667 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert1> current NULL pending VOID_PENDING, desired next READY
0:00:00.143391737 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert1> completed state change to READY
0:00:00.143394377 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert1> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.143398877 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'videoconvert1' changed state to 2(READY) successfully
0:00:00.143402047 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<avdec_h264-1> current NULL pending VOID_PENDING, desired next READY
0:00:00.143404597 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<avdec_h264-1> completed state change to READY
0:00:00.143407277 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<avdec_h264-1> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.143410487 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'avdec_h264-1' changed state to 2(READY) successfully
0:00:00.143413207 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse1> current NULL pending VOID_PENDING, desired next READY
0:00:00.143415557 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to READY
0:00:00.143417827 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.143421067 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'h264parse1' changed state to 2(READY) successfully
0:00:00.143424797 5785 0x75109c011560 INFO GST_STATES gstelement.c:2796:gst_element_continue_state:<wg_transform> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:00.143432117 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<wg_transform> notifying about state-changed NULL to READY (PAUSED pending)
0:00:00.143436077 5785 0x75109c011560 INFO GST_STATES gstelement.c:2804:gst_element_continue_state:<wg_transform> continue state change READY to PAUSED, final PAUSED
0:00:00.143440617 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert1> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.143445227 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert1> completed state change to PAUSED
0:00:00.143447637 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert1> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.143450957 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'videoconvert1' changed state to 3(PAUSED) successfully
0:00:00.143453877 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<avdec_h264-1> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.143459627 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<avdec_h264-1> completed state change to PAUSED
0:00:00.143461987 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<avdec_h264-1> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.143465207 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'avdec_h264-1' changed state to 3(PAUSED) successfully
0:00:00.143467927 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse1> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.143480667 5785 0x75109c011560 TRACE WINE wg_transform.c:296:transform_src_query_cb: transform 0x75109c450420, ignoring scheduling query: 0x75109c5afe60, GstQueryScheduling, flags=(GstSchedulingFlags)0, minsize=(int)1, maxsize=(int)-1, align=(int)0;
0:00:00.143518127 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to PAUSED
0:00:00.143521047 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.143524617 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'h264parse1' changed state to 3(PAUSED) successfully
0:00:00.143527797 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<wg_transform> completed state change to PAUSED
0:00:00.143530107 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<wg_transform> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.143533067 5785 0x75109c011560 INFO GST_STATES gstbin.c:2070:gst_bin_get_state_func:<wg_transform> getting state
0:00:00.143543047 5785 0x75109c011560 TRACE WINE wg_transform.c:457:transform_sink_event_cb: transform 0x75109c450420, ignoring stream-start event: 0x75109c45ce50, time 99:99:99.999999999, seq-num 56, GstEventStreamStart, stream-id=(string)stream, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE;
0:00:00.143550247 5785 0x75109c011560 INFO GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, codec_data=(buffer)00000001674d4034959003c0043ec04400000fa000075302100000000168eb8f20, stream-format=(string)byte-stream, alignment=(string)au
0:00:00.143557737 5785 0x75109c011560 WARN h264parse gsth264parse.c:3707:gst_h264_parse_set_caps:<h264parse1> H.264 bytestream caps with codec_data is not expected, send SPS/PPS in-band with data or in streamheader field
0:00:00.143562297 5785 0x75109c011560 WARN h264parse gsth264parse.c:3718:gst_h264_parse_set_caps:<h264parse1> refused caps video/x-h264, codec_data=(buffer)00000001674d4034959003c0043ec04400000fa000075302100000000168eb8f20, stream-format=(string)byte-stream, alignment=(string)au
0:00:00.143567117 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking videoconvert1:src(0x75109c458010) and '':sink(0x75109c452470)
0:00:00.143571067 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked videoconvert1:src and '':sink
0:00:00.143577057 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking '':src(0x75109c452180) and h264parse1:sink(0x75109c453960)
0:00:00.143579737 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked '':src and h264parse1:sink
0:00:00.143583947 5785 0x75109c011560 LOG WINE wg_allocator.c:264:wg_allocator_destroy: allocator 0x75109c450ea0
0:00:00.143586537 5785 0x75109c011560 LOG WINE wg_allocator.c:175:wg_allocator_finalize: allocator 0x75109c450ea0
0:00:00.143588757 5785 0x75109c011560 INFO WINE wg_allocator.c:273:wg_allocator_destroy: Destroyed buffer allocator 0x75109c450ea0
0:00:00.143594277 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert1> current PAUSED pending VOID_PENDING, desired next READY
0:00:00.143599107 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert1> completed state change to READY
0:00:00.143601527 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert1> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:00.143605057 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'videoconvert1' changed state to 2(READY) successfully
0:00:00.143607827 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<avdec_h264-1> current PAUSED pending VOID_PENDING, desired next READY
0:00:00.143613577 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<avdec_h264-1> completed state change to READY
0:00:00.143615847 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<avdec_h264-1> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:00.143618957 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'avdec_h264-1' changed state to 2(READY) successfully
0:00:00.143621567 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse1> current PAUSED pending VOID_PENDING, desired next READY
0:00:00.143631497 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to READY
0:00:00.143633937 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:00.143637187 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'h264parse1' changed state to 2(READY) successfully
0:00:00.143640537 5785 0x75109c011560 INFO GST_STATES gstelement.c:2796:gst_element_continue_state:<wg_transform> committing state from PAUSED to READY, pending NULL, next NULL
0:00:00.143642887 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<wg_transform> notifying about state-changed PAUSED to READY (NULL pending)
0:00:00.143645727 5785 0x75109c011560 INFO GST_STATES gstelement.c:2804:gst_element_continue_state:<wg_transform> continue state change READY to NULL, final NULL
0:00:00.143649567 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert1> current READY pending VOID_PENDING, desired next NULL
0:00:00.143652527 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert1> completed state change to NULL
0:00:00.143654947 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert1> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:00.143658137 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'videoconvert1' changed state to 1(NULL) successfully
0:00:00.143660947 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<avdec_h264-1> current READY pending VOID_PENDING, desired next NULL
0:00:00.143663877 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<avdec_h264-1> completed state change to NULL
0:00:00.143666077 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<avdec_h264-1> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:00.143669217 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'avdec_h264-1' changed state to 1(NULL) successfully
0:00:00.143671717 5785 0x75109c011560 INFO GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse1> current READY pending VOID_PENDING, desired next NULL
0:00:00.143674517 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to NULL
0:00:00.143676697 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:00.143679777 5785 0x75109c011560 INFO GST_STATES gstbin.c:2939:gst_bin_change_state_func:<wg_transform> child 'h264parse1' changed state to 1(NULL) successfully
0:00:00.143682457 5785 0x75109c011560 INFO GST_STATES gstelement.c:2824:gst_element_continue_state:<wg_transform> completed state change to NULL
0:00:00.143684697 5785 0x75109c011560 INFO GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<wg_transform> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:00.143689597 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking avdec_h264-1:src(0x75109c456910) and videoconvert1:sink(0x75109c4585e0)
0:00:00.143692887 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked avdec_h264-1:src and videoconvert1:sink
0:00:00.143696137 5785 0x75109c011560 INFO GST_PARENTAGE gstbin.c:1805:gst_bin_remove_func:<wg_transform> removed child "videoconvert1"
0:00:00.143700837 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3400:gst_element_dispose:<videoconvert1> 0x75109c459d90 dispose
0:00:00.143703117 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<videoconvert1> removing pad 'sink'
0:00:00.143706517 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<videoconvert1> removing pad 'src'
0:00:00.143709297 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3446:gst_element_dispose:<videoconvert1> 0x75109c459d90 parent class dispose
0:00:00.143711977 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3478:gst_element_finalize:<videoconvert1> 0x75109c459d90 finalize
0:00:00.143713997 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3483:gst_element_finalize:<videoconvert1> 0x75109c459d90 finalize parent
0:00:00.143717187 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking h264parse1:src(0x75109c453bb0) and avdec_h264-1:sink(0x75109c4566c0)
0:00:00.143720287 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked h264parse1:src and avdec_h264-1:sink
0:00:00.143723277 5785 0x75109c011560 INFO GST_PARENTAGE gstbin.c:1805:gst_bin_remove_func:<wg_transform> removed child "avdec_h264-1"
0:00:00.143726017 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3400:gst_element_dispose:<avdec_h264-1> 0x75109c456250 dispose
0:00:00.143728017 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<avdec_h264-1> removing pad 'sink'
0:00:00.143730497 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<avdec_h264-1> removing pad 'src'
0:00:00.143733257 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3446:gst_element_dispose:<avdec_h264-1> 0x75109c456250 parent class dispose
0:00:00.143736687 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3478:gst_element_finalize:<avdec_h264-1> 0x75109c456250 finalize
0:00:00.143738597 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3483:gst_element_finalize:<avdec_h264-1> 0x75109c456250 finalize parent
0:00:00.143741897 5785 0x75109c011560 INFO GST_PARENTAGE gstbin.c:1805:gst_bin_remove_func:<wg_transform> removed child "h264parse1"
0:00:00.143744547 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3400:gst_element_dispose:<h264parse1> 0x75109c452b50 dispose
0:00:00.143746487 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<h264parse1> removing pad 'sink'
0:00:00.143748917 5785 0x75109c011560 INFO GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<h264parse1> removing pad 'src'
0:00:00.143751587 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3446:gst_element_dispose:<h264parse1> 0x75109c452b50 parent class dispose
0:00:00.143755697 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3478:gst_element_finalize:<h264parse1> 0x75109c452b50 finalize
0:00:00.143757677 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3483:gst_element_finalize:<h264parse1> 0x75109c452b50 finalize parent
0:00:00.143759797 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3400:gst_element_dispose:<wg_transform> 0x75109c4508e0 dispose
0:00:00.143761737 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3446:gst_element_dispose:<wg_transform> 0x75109c4508e0 parent class dispose
0:00:00.143763697 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3478:gst_element_finalize:<wg_transform> 0x75109c4508e0 finalize
0:00:00.143765657 5785 0x75109c011560 INFO GST_REFCOUNTING gstelement.c:3483:gst_element_finalize:<wg_transform> 0x75109c4508e0 finalize parent
**0:00:00.143767757 5785 0x75109c011560 ERROR WINE wg_transform.c:757:wg_transform_create: Failed to create winegstreamer transform.**
I'm testing on Arch Linux, fully updated with a 6900XT. Gstreamer is installed and working in other applications (and older builds of experimental).
Is this a known issue? Is it supposed to work in tandem with some other component in proton that I'm missing? Am I missing some library?
No, it's supposed to work but we also use a limited number of GStreamer plugins so it's possible that it broke with a wider set. It looks like for instance that h264parse is unhappy here, we don't have it in Proton.
Does a patch like this helps?
diff --git a/dlls/winegstreamer/wg_media_type.c b/dlls/winegstreamer/wg_media_type.c
index f45ba294a2c..c610ae17c32 100644
--- a/dlls/winegstreamer/wg_media_type.c
+++ b/dlls/winegstreamer/wg_media_type.c
@@ -302,7 +302,7 @@ static void init_caps_from_video_h264(GstCaps *caps, const MFVIDEOFORMAT *format
gst_structure_remove_field(gst_caps_get_structure(caps, 0), "format");
gst_structure_set_name(gst_caps_get_structure(caps, 0), "video/x-h264");
- gst_caps_set_simple(caps, "stream-format", G_TYPE_STRING, "byte-stream", NULL);
+ gst_caps_set_simple(caps, "stream-format", G_TYPE_STRING, format_size - sizeof(*format) ? "avc" : "byte-stream", NULL);
gst_caps_set_simple(caps, "alignment", G_TYPE_STRING, "au", NULL);
}
@rnbrznr That doesn't work unfortunately, it gives the same exact error. I also tried hardcoding that "avc" string just to be safe, no effect. I quickly added a breakpoint to see if that code was even being executed and it looks like it's not so there must be a problem earlier on, maybe it doesn't detect that it's h264?
Just retested after today's commits, it's still broken. h264, h265, vp8, vp9, nothing plays in both games and applications.
@rnbrznr how are you building and testing your new code? I must be doing something wrong...
Sorry, we're not really testing with full-featured GStreamer, so it might be broken in some ways. It's not very much a supported use case, although I would obviously like it work for Wine upstream. Please note that whatever is in bleeding-edge is also very experimental and only there to get some wider feedback. I will suggest to simply not include the changes in your build if they are causing problems.
The change I suggested should help as far as I can see from your log 0:00:00.143557737 5785 0x75109c011560 WARN h264parse gsth264parse.c:3707:gst_h264_parse_set_caps:<h264parse1> H.264 bytestream caps with codec_data is not expected, send SPS/PPS in-band with data or in streamheader field. I've seen it locally when working on patches for upstream, but I don't know why the fix doesn't work for you.
I know experimental is just for testing, that's why I build it regularly, to check for regressions, stability, compatibility with new games, etc.
I asked because it seems odd that everything I throw at it doesn't work, I want to be sure that I'm not building or using it wrong.
What applications and videos are you testing it with?
This issue is also affecting games like Throne and Liberty on Steam. Ingame videos dont work on experimental.
@daegalus These commits are not in experimental yet, they're only in bleeding-edge. If it works with stable, some other change must have broken that game, if you have the time you should do a bisect and find out the exact commit.
@adolfintel The new media source work was temporarily pulled from bleeding edge in order to work on it more and fix some found regressions. It will likely be back within a couple of weeks.
Thanks for the heads up @alasky17
Will you leave the WINE_NEW_MEDIA_SOURCE variable for regression testing?
@adolfintel Disabling WINE_NEW_MEDIA_SOURCE with the variable will be impossible with the degree to which the media code is being altered by the new patches (as you might have already noticed when it was in bleeding-edge last month). However, the new media source will not be in a stable release for a long time so that folks have a fallback while we fix regressions (as well as a version to regression-check against :). While the new media source changes are only in bleeding-edge (which will be a lot more time than usual) folks can also compare bleeding-edge to "regular experimental" when determining if something is regressive.
Looks like the new media source has been deployed, and it works :)
I noticed that some games play H264 videos with the wrong color space though, they look washed out.
Of the ones that I have tried so far, A Plague Tale Requiem (immediately visible in the intro videos) and a non-steam indie game based on stepmania.
I'm very interested in the new media source and I'll be testing every game in my library for regressions. I'll update this post if I find any problem.
Update 1: Trombone Champ (Unity 2019) also has washed out colors playing H264 videos
Update 2: UE4/5 have no issues with H264
With the reintroduction of the new media source, the game Ghostbusters: The Video Game Remastered is now able to play 4K MP4 videos! However, some videos display a green bar at the bottom.
From what I understand (though I haven't personally tested this), this issue wasn't present in the initial implementation of the new media source, all videos played without problems back then.
Additionally, attempting to play the "Bonus Commercial Footage" video from the "Extras > Videos" section causes the game to crash.
Can confirm the issue with Ghostbusters Remastered. It's minor but it's there
@adolfintel I'm not seeing any washed out colors with Plague Tale: Requiem with my "standard" setup. Could you upload some side-by-side screenshots of where you see the issue? Also, are you still using the same setup as before with full-featured Gstreamer etc?
Yes, I'm still using a full gstreamer. I haven't seen many issues to be honest, if anything the new media source has improved compatibility with some games like starship troopers that didn't want to play videos in crappy formats like wmv.
Anyway, screenshot of requiem with the current bleeding-edge:
Same intro video in proton stable:
I see the same washed out colors in the handful of unity games that use mp4 as well, but I haven't found other games with this issue.
@KeyofBlueS I'm not seeing the green stripe. Could you please copy your system information from Steam (Steam -> Help -> System Information and Steam -> Help -> Steam Runtime Diagnostics) and put each in a gist, then include a link to the gists? Are you also using the full gstreamer setup instead of the official Proton one?
Also - I don't have access to that bonus video :( If there is a way for you to upload the game files so that I can get access, that would be really helpful :)
@adolfintel Thank you for the screenshots! I see it now -- will investigate further :)
Hi @alasky17, thanks for getting back!
Here are the logs you requested: System Information Steam Runtime Diagnostics
I dont know about gstreamer, I believe I'm using the official Proton setup.
When you mentioned "upload the game files", were you referring to that specific video? If so, you can find it in your game files at steamapps/common/Ghostbusters The Video Game Remastered/video/BR_commercial.mp4.
Or did you mean a savegame where that extra content is unlocked? If that's the case, I've attached it here: gbtvgr_savefile.zip
Just extract the archive and place the files in "${HOME}/.local/share/Steam/steamapps/compatdata/1449280/pfx/drive_c/users/steamuser/Documents/GHOSTBUSTERS/"
Let me know if there's anything else you need!
@adolfintel The "washed out" issue with some videos like Plague Tale Requiem should be fixed with current bleeding-edge. Please let me know if you see this with any other games! (and exactly where in the games so I can repro easily :). A feature needed to be implemented for a particular video type, and there could be other video types that need something similar that we've missed. Thank you again for your attention to detail and reporting!
@KeyofBlueS Thank you! That is exactly what I was asking for :) Weirdly, I'm not seeing the green stripe OR the crash on the bonus videos with your save (which worked for me to test the right bit, thanks again!!!) ... Could you get 2 logs with both failures? It would be really great if you can get one log with current experimental (not-bleeding-edge) and one with bleeding-edge so that we have something to compare against. Please use PROTON_LOG=+quartz,+strmbase,+strmbase_qc,+gstreamer,+amstream,+qcap,+qcap_v4l,+qedit,+mciqtz,+mci,+mfplat,+gstreamer,+evr,+dxva2,+wmvcore %command%
Here are the Proton logs you requested!
Please note that when using the standard Proton Experimental, the game plays lower resolution OGV videos. Only with the current Proton Bleeding-Edge it plays higher resolution MP4 videos.
Additionally, when capturing the Proton bleeding-edge log, the game doesn't "crash to desktop" at the bonus video; instead, it freezes on a black screen, requiring a forced stop. In this scenario, the Proton log file grows significantly in size (I stopped the game as quickly as possible, within a few seconds, but the log still ended up being around 550MB), which is why I've compressed and uploaded the logs in a zip file.
Thank you for taking the time to look into this issue. I appreciate your help!
@alasky17 Both APT Requiem and Unity games seem to work properly with the current bleeding-edge. Awesome work :)
@KeyofBlueS Thank you for the logs! We figured out what was going on - the game picks up the GPU and monitor, and doesn't play the MP4 videos for certain combinations (which is Windows behavior) so I was accidentally still looking at the ogv video. We will continue to work on these bugs (the green line and the issues with the bonus videos), but it could be some time before they are fixed properly. I believe they are not actually "regressions" caused by new media source, but merely "regular" video playback bugs with the MP4 videos that are only just now working at all.
Thank you again for all the info - we will plan to avoid enabling the MP4 videos in stable Proton versions until these bugs are also fixed :)
Thank you for taking a look at this! Feel free to reach out if you need anything further regarding this issue.
Best regards.
It looks like the latest Bleeding-Edge update, I'm guessing thanks to commit https://github.com/ValveSoftware/wine/commit/8a4c3f608c701d99a33de45c2cfb6b1766763bbc, has mostly resolved the green bar issue, that now only appears for a split second at the start of the initial "logo" video!
The crash during the extra "Bonus Commercial Footage" video is still happening.
@KeyofBlueS Thank you for the update! Glad the green bar fix is working for you :) WRT the crash - after some investigation it looks like the root cause is that the mp4 video is simply much larger (unsurprisingly) and Proton struggles to keep up with playing it. We are always trying to make Proton more efficient at video playback to improve perf in general, but that is a longer road than fixing something that is specifically "wrong" like the green stripe :(
@alasky17 I really appreciate the effort in looking into the issue.
I'm not entirely sure what you mean by "the video is simply much larger".
In any case, I just compared the video that caused the crash, "BR_commercial.mp4", with the other mp4 files using the tool "mediainfo". I noticed that it's the only one with an audio sampling rate of 44.1 kHz, while the others use 48.0 kHz. So I tried converting the audio in "BR_commercial.mp4" from 44.1 kHz to 48.0 kHz using the following steps:
Navigate to the directory containing the video files (make sure to replace 'path_to_steamapps_folder' with the actual path to your steamapps directory)
cd "path_to_steamapps_folder/steamapps/common/Ghostbusters The Video Game Remastered/video/"
Rename the original BR_commercial.mp4 to BR_commercial_44100Hz.mp4 for backup purposes
mv "./BR_commercial.mp4" "./BR_commercial_44100Hz.mp4"
Use ffmpeg to copy the video stream (-c:v copy) without re-encoding
At the same time, convert the audio sample rate to 48.0 kHz (-ar 48000)
Save the output back as BR_commercial.mp4, which replaces the original file
ffmpeg -i "./BR_commercial_44100Hz.mp4" -c:v copy -ar 48000 "./BR_commercial.mp4"
After doing this, the video no longer causes the game to crash. Given this experiment, it seems possible that the issue might not be on the video side, but rather on the audio side, since switching the audio sampling rate resolved the crash. Hopefully, this information is helpful.
And thanks again for investigating the issue!