feuera commented 5 months ago

I am on arch linux 6.8.7-arch1-1 and video window seems unable to open. Tried different sinks, recompiled package after upgrade. It seems to work 1 in 30 attempts without having anything done. In log the only thing I can find for difference: X11 UxPlay Window not found in 5 search attempts

Iphone 12 mini 17.4.1 used ports seem to be different as well but using option -p did not make a difference.

In my last session where it worked I stopped screen mirror on phone and restarted it. And it did not work any more on the second attempt.

Have no idea what else to try ...

fduncanh commented 5 months ago

ON Arch 6.8.2-arch2-1 (did you really mean 6.8.7-arch-1 ?)

works for me. what are you running uxplay on? x86-64 or other architecture?

did you try uxplay -vs waylandsink ?

what does uxplay -d show?

post it here, maybe.

feuera commented 5 months ago

yes

Linux g9studio 6.8.7-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 17 Apr 2024 15:20:28 +0000 x86_64 GNU/Linux

output: uxplay -d (running i3 wm, so no wayland, although same behaviour on Plasma, sway, ..)

UxPlay 1.68: An Open-Source AirPlay mirroring and audio-streaming server.
Audio format 1: AAC-ELD 44100/2
GStreamer audio pipeline 1: "appsrc name=audio_source ! queue ! avdec_aac ! audioconvert ! audioresample ! volume name=volume ! level ! autoaudiosink sync=true"
Audio format 2: ALAC 44100/16/2
GStreamer audio pipeline 2: "appsrc name=audio_source ! queue ! avdec_alac ! audioconvert ! audioresample ! volume name=volume ! level ! autoaudiosink sync=false"
GStreamer video pipeline will be:
"appsrc name=video_source ! queue ! h264parse ! decodebin ! videoconvert ! autovideosink name=video_sink sync=true"
Initialized GStreamer video renderer
using system MAC address 00:93:37:7a:31:cc
Initialized server socket(s)
register_dnssd: advertised AirPlay service with "Features" code = 0x527FFEE6
Accepted IPv4 client on socket 451
Local: 192.168.0.110
Remote: 192.168.0.6
Open connections: 1
httpd receiving on socket 451
conn_request

GET /info RTSP/1.0
X-Apple-ProtocolVersion: 1
Content-Length: 70
Content-Type: application/x-apple-binary-plist
CSeq: 0
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>qualifier</key>
    <array>
        <string>txtAirPlay</string>
    </array>
</dict>
</plist>

Handling request GET with URL /info

RTSP/1.0 200 OK 
CSeq: 0 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 1077 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>txtAirPlay</key>
    <data>
    GmRldmljZWlkPTAwOjkzOjM3OjdhOjMxOmNjF2ZlYXR1cmVzPTB4NTI3RkZFRTYsMHgw
    CWZsYWdzPTB4NBBtb2RlbD1BcHBsZVRWMywyQ3BrPTlmNDJkMTc3N2E2NDgxZDhkMGFi
    ZGI1OGU1NzZmN2ZhMDhlMDUzZjUyY2VmNmI4OGNlYzVkNTI1YWM4YjQ4YjIIcHc9ZmFs
    c2UncGk9MmUzODgwMDYtMTNiYS00MDQxLTlhNjctMjVkZDRhNDNkNTM2DnNyY3ZlcnM9
    MjIwLjY4BHZ2PTI=
    </data>
    <key>features</key>
    <integer>1384120038</integer>
    <key>name</key>
    <string>UxPlay@g9studio</string>
    <key>audioFormats</key>
    <array>
        <dict>
            <key>type</key>
            <integer>100</integer>
            <key>audioInputFormats</key>
            <integer>67108860</integer>
            <key>audioOutputFormats</key>
            <integer>67108860</integer>
        </dict>
        <dict>
            <key>type</key>
            <integer>101</integer>
            <key>audioInputFormats</key>
            <integer>67108860</integer>
            <key>audioOutputFormats</key>
            <integer>67108860</integer>
        </dict>
    </array>
    <key>pi</key>
    <string>2e388006-13ba-4041-9a67-25dd4a43d536</string>
    <key>vv</key>
    <integer>2</integer>
    <key>statusFlags</key>
    <integer>68</integer>
    <key>keepAliveLowPower</key>
    <integer>1</integer>
    <key>sourceVersion</key>
    <string>220.68</string>
    <key>pk</key>
    <data>
    n0LRd3pkgdjQq9tY5Xb3+gjgU/Us72uIzsXVJayLSLI=
    </data>
    <key>keepAliveSendStatsAsBody</key>
    <integer>1</integer>
    <key>deviceID</key>
    <string>00:93:37:7a:31:cc</string>
    <key>audioLatencies</key>
    <array>
        <dict>
            <key>outputLatencyMicros</key>
            <false/>
            <key>type</key>
            <integer>100</integer>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <false/>
        </dict>
        <dict>
            <key>outputLatencyMicros</key>
            <false/>
            <key>type</key>
            <integer>101</integer>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <false/>
        </dict>
    </array>
    <key>model</key>
    <string>AppleTV3,2</string>
    <key>macAddress</key>
    <string>00:93:37:7a:31:cc</string>
    <key>displays</key>
    <array>
        <dict>
            <key>uuid</key>
            <string>e0ff8a27-6738-3d56-8a16-cc53aacee925</string>
            <key>widthPhysical</key>
            <false/>
            <key>heightPhysical</key>
            <false/>
            <key>width</key>
            <integer>1920</integer>
            <key>height</key>
            <integer>1080</integer>
            <key>widthPixels</key>
            <integer>1920</integer>
            <key>heightPixels</key>
            <integer>1080</integer>
            <key>rotation</key>
            <false/>
            <key>refreshRate</key>
            <integer>60</integer>
            <key>maxFPS</key>
            <integer>30</integer>
            <key>overscanned</key>
            <false/>
            <key>features</key>
            <integer>14</integer>
        </dict>
    </array>
</dict>
</plist>

httpd receiving on socket 451
conn_request

POST /fp-setup RTSP/1.0
X-Apple-ET: 32
Content-Length: 16
Content-Type: application/octet-stream
CSeq: 1
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

46 50 4c 59 03 01 01 00 00 00 00 04 02 00 03 bb 

Handling request POST with URL /fp-setup

RTSP/1.0 200 OK 
CSeq: 1 
Server: AirTunes/220.68 
Content-Type: application/octet-stream 
Content-Length: 142 

46 50 4c 59 03 01 02 00 00 00 00 82 02 03 90 01 
e1 72 7e 0f 57 f9 f5 88 0d b1 04 a6 25 7a 23 f5 
cf ff 1a bb e1 e9 30 45 25 1a fb 97 eb 9f c0 01 
1e be 0f 3a 81 df 5b 69 1d 76 ac b2 f7 a5 c7 08 
e3 d3 28 f5 6b b3 9d bd e5 f2 9c 8a 17 f4 81 48 
7e 3a e8 63 c6 78 32 54 22 e6 f7 8e 16 6d 18 aa 
7f d6 36 25 8b ce 28 72 6f 66 1f 73 88 93 ce 44 
31 1e 4b e6 c0 53 51 93 e5 ef 72 e8 68 62 33 72 
9c 22 7d 82 0c 99 94 45 d8 92 46 c8 c3 59 

httpd receiving on socket 451
conn_request

POST /fp-setup RTSP/1.0
X-Apple-ET: 32
Content-Length: 164
Content-Type: application/octet-stream
CSeq: 2
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

46 50 4c 59 03 01 03 00 00 00 00 98 03 8f 1a 9c 
98 bc 11 8f 39 4d 92 ab a2 35 fc f5 4f 47 5c 5b 
00 d5 17 45 1d 1b 29 40 5c 55 9b 22 e3 55 bd 77 
2a 69 f1 b5 77 e8 ea f5 da 95 63 a4 98 fc 6a f9 
7e c6 62 c0 87 0b 9e 3b 8a b7 d0 23 97 5e df 2c 
f3 0e be f3 8d d8 64 b2 77 01 09 84 7a ef 5c a6 
9f 07 88 ae f7 4d a6 ea 0b 54 d1 1d 2e 90 74 4b 
00 92 d4 1c 4a 8c ac be 03 9e 2a 79 59 ff ec e8 
74 85 8d 88 bb c1 31 0e ff f9 52 c1 15 f7 10 35 
3e 2a c6 f4 40 a4 08 ce 35 ef b7 85 e7 4f 32 69 
d2 51 d1 9f 

Handling request POST with URL /fp-setup

RTSP/1.0 200 OK 
CSeq: 2 
Server: AirTunes/220.68 
Content-Type: application/octet-stream 
Content-Length: 32 

46 50 4c 59 03 01 04 00 00 00 00 14 3e 2a c6 f4 
40 a4 08 ce 35 ef b7 85 e7 4f 32 69 d2 51 d1 9f 

httpd receiving on socket 451
conn_request

SETUP rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
Content-Length: 624
Content-Type: application/x-apple-binary-plist
CSeq: 3
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>et</key>
    <integer>32</integer>
    <key>statsCollectionEnabled</key>
    <false/>
    <key>eiv</key>
    <data>
    Aux8liqGdxqQgYfLyHAhOg==
    </data>
    <key>sessionUUID</key>
    <string>F11AF34D-F0A8-48A4-A4C7-2B2C09453410</string>
    <key>timingProtocol</key>
    <string>NTP</string>
    <key>osName</key>
    <string>iPhone OS</string>
    <key>osBuildVersion</key>
    <string>21E236</string>
    <key>sourceVersion</key>
    <string>760.20.1</string>
    <key>timingPort</key>
    <integer>49960</integer>
    <key>isScreenMirroringSession</key>
    <true/>
    <key>osVersion</key>
    <string>17.4.1</string>
    <key>ekey</key>
    <data>
    RlBMWQECAQAAAAA8AAAAAIrIAk6ajRlJtQoDlm6XIFEAAAAQdYOJqMKtE/0BtZdm6/mY
    cNnkhT0Nv2hdpaPv02jo55pQbGpD
    </data>
    <key>sessionCorrelationUUID</key>
    <string>2E07B722-01F4-463C-AD09-26D2EBE90C35</string>
    <key>deviceID</key>
    <string>FC:66:CF:DF:2E:52</string>
    <key>model</key>
    <string>iPhone13,1</string>
    <key>name</key>
    <string>Meins</string>
    <key>macAddress</key>
    <string>32:69:6E:F1:56:8E</string>
</dict>
</plist>

Handling request SETUP with URL rtsp://192.168.0.110/17373466028610701476
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
SETUP 1
connection request from Meins (iPhone13,1) with deviceID = FC:66:CF:DF:2E:52

eiv_len = 16
16 byte aesiv (needed for AES-CBC audio decryption iv):
02 ec 7c 96 2a 86 77 1a 90 81 87 cb c8 70 21 3a 

ekey_len = 72
ekey:
46 50 4c 59 01 02 01 00 00 00 00 3c 00 00 00 00 
8a c8 02 4e 9a 8d 19 49 b5 0a 03 96 6e 97 20 51 
00 00 00 10 75 83 89 a8 c2 ad 13 fd 01 b5 97 66 
eb f9 98 70 d9 e4 85 3d 0d bf 68 5d a5 a3 ef d3 
68 e8 e7 9a 50 6c 6a 43 

fairplay_decrypt ret = 0
16 byte aeskey (fairplay-decrypted from ekey):
0a c8 2d 9d fb c5 eb 48 23 aa ba 12 c8 8f a3 21 

Client identified as User-Agent: AirPlay/760.20.1
timing_rport = 49960
raop_ntp parse remote ip = 192.168.0.6
raop_ntp starting time
raop_ntp local timing port socket 452 port UDP 44392

raop_ntp send time type_t=82 packetlen = 32, now = 1713524234.829391
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 cc cc 8a d4 52 fc 33 

raop_rtp parse remote ip = 192.168.0.6
raop_rtp_mirror parse remote ip = 192.168.0.6
eport = 42735, tport = 44392

RTSP/1.0 200 OK 
CSeq: 3 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 77 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>timingPort</key>
    <integer>44392</integer>
    <key>eventPort</key>
    <integer>42735</integer>
</dict>
</plist>

raop_ntp receive time type_t=83 packetlen = 32, now = 1713524234.840508 t1 = 368509.622027, t2 = 368509.622108
80 d3 00 07 00 00 00 00 e9 cc cc 8a d4 52 fc 33 
83 b0 1d fd 9f 3d 30 53 83 b0 1d fd 9f 42 7b c9 

raop_ntp sync correction = -1713155725212881886
Accepted IPv4 client on socket 453
Local: 192.168.0.110
Remote: 192.168.0.6
Open connections: 2
httpd receiving on socket 451
conn_request

GET /info RTSP/1.0
X-Apple-ProtocolVersion: 1
CSeq: 4
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

Handling request GET with URL /info

RTSP/1.0 200 OK 
CSeq: 4 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 1077 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>txtAirPlay</key>
    <data>
    GmRldmljZWlkPTAwOjkzOjM3OjdhOjMxOmNjF2ZlYXR1cmVzPTB4NTI3RkZFRTYsMHgw
    CWZsYWdzPTB4NBBtb2RlbD1BcHBsZVRWMywyQ3BrPTlmNDJkMTc3N2E2NDgxZDhkMGFi
    ZGI1OGU1NzZmN2ZhMDhlMDUzZjUyY2VmNmI4OGNlYzVkNTI1YWM4YjQ4YjIIcHc9ZmFs
    c2UncGk9MmUzODgwMDYtMTNiYS00MDQxLTlhNjctMjVkZDRhNDNkNTM2DnNyY3ZlcnM9
    MjIwLjY4BHZ2PTI=
    </data>
    <key>features</key>
    <integer>1384120038</integer>
    <key>name</key>
    <string>UxPlay@g9studio</string>
    <key>audioFormats</key>
    <array>
        <dict>
            <key>type</key>
            <integer>100</integer>
            <key>audioInputFormats</key>
            <integer>67108860</integer>
            <key>audioOutputFormats</key>
            <integer>67108860</integer>
        </dict>
        <dict>
            <key>type</key>
            <integer>101</integer>
            <key>audioInputFormats</key>
            <integer>67108860</integer>
            <key>audioOutputFormats</key>
            <integer>67108860</integer>
        </dict>
    </array>
    <key>pi</key>
    <string>2e388006-13ba-4041-9a67-25dd4a43d536</string>
    <key>vv</key>
    <integer>2</integer>
    <key>statusFlags</key>
    <integer>68</integer>
    <key>keepAliveLowPower</key>
    <integer>1</integer>
    <key>sourceVersion</key>
    <string>220.68</string>
    <key>pk</key>
    <data>
    n0LRd3pkgdjQq9tY5Xb3+gjgU/Us72uIzsXVJayLSLI=
    </data>
    <key>keepAliveSendStatsAsBody</key>
    <integer>1</integer>
    <key>deviceID</key>
    <string>00:93:37:7a:31:cc</string>
    <key>audioLatencies</key>
    <array>
        <dict>
            <key>outputLatencyMicros</key>
            <false/>
            <key>type</key>
            <integer>100</integer>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <false/>
        </dict>
        <dict>
            <key>outputLatencyMicros</key>
            <false/>
            <key>type</key>
            <integer>101</integer>
            <key>audioType</key>
            <string>default</string>
            <key>inputLatencyMicros</key>
            <false/>
        </dict>
    </array>
    <key>model</key>
    <string>AppleTV3,2</string>
    <key>macAddress</key>
    <string>00:93:37:7a:31:cc</string>
    <key>displays</key>
    <array>
        <dict>
            <key>uuid</key>
            <string>e0ff8a27-6738-3d56-8a16-cc53aacee925</string>
            <key>widthPhysical</key>
            <false/>
            <key>heightPhysical</key>
            <false/>
            <key>width</key>
            <integer>1920</integer>
            <key>height</key>
            <integer>1080</integer>
            <key>widthPixels</key>
            <integer>1920</integer>
            <key>heightPixels</key>
            <integer>1080</integer>
            <key>rotation</key>
            <false/>
            <key>refreshRate</key>
            <integer>60</integer>
            <key>maxFPS</key>
            <integer>30</integer>
            <key>overscanned</key>
            <false/>
            <key>features</key>
            <integer>14</integer>
        </dict>
    </array>
</dict>
</plist>

httpd receiving on socket 451
conn_request

GET_PARAMETER rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
Content-Length: 8
Content-Type: text/parameters
CSeq: 5
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

volume 

Handling request GET_PARAMETER with URL rtsp://192.168.0.110/17373466028610701476

RTSP/1.0 200 OK 
CSeq: 5 
Server: AirTunes/220.68 
Content-Type: text/parameters 
Content-Length: 13 

volume: 0.0 

httpd receiving on socket 451
conn_request

RECORD rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
CSeq: 6
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

Handling request RECORD with URL rtsp://192.168.0.110/17373466028610701476
raop_handler_record

RTSP/1.0 200 OK 
CSeq: 6 
Server: AirTunes/220.68 
Audio-Latency: 11025 
Audio-Jack-Status: connected; type=analog 

httpd receiving on socket 451
conn_request

SETUP rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
Content-Length: 204
Content-Type: application/x-apple-binary-plist
CSeq: 7
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>streams</key>
    <array>
        <dict>
            <key>timestampInfo</key>
            <array>
                <dict>
                    <key>name</key>
                    <string>SubSu</string>
                </dict>
                <dict>
                    <key>name</key>
                    <string>BePxT</string>
                </dict>
                <dict>
                    <key>name</key>
                    <string>AfPxT</string>
                </dict>
                <dict>
                    <key>name</key>
                    <string>BefEn</string>
                </dict>
                <dict>
                    <key>name</key>
                    <string>EmEnc</string>
                </dict>
            </array>
            <key>latencyMs</key>
            <integer>100</integer>
            <key>type</key>
            <integer>110</integer>
            <key>streamConnectionID</key>
            <integer>-5964840691543290720</integer>
        </dict>
    </array>
</dict>
</plist>

Handling request SETUP with URL rtsp://192.168.0.110/17373466028610701476
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
type = 110
streamConnectionID (needed for AES-CTR video decryption key and iv): 12481903382166260896
raop_rtp_mirror starting mirroring
raop_rtp_mirror local data port socket 454 port TCP 39547
Mirroring initialized successfully

RTSP/1.0 200 OK 
CSeq: 7 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 85 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>streams</key>
    <array>
        <dict>
            <key>dataPort</key>
            <integer>39547</integer>
            <key>type</key>
            <integer>110</integer>
        </dict>
    </array>
</dict>
</plist>

raop_rtp_mirror accepting client

Received unencrypted codec packet from client: payload_size 37 header 01 00 16 01  ts_client = 368510.017368
raop_rtp_mirror: unidentified extra header data  710.000000, 0.000000
begin video stream wxh = 500x1080; source 500x1080
raop_rtp_mirror width_source = 500.000000 height_source = 1080.000000 width = 500.000000 height = 1080.000000
raop_rtp_mirror: SPS+PPS header size = 6
raop_rtp_mirror h264 SPS+PPS header:
01 64 00 1f ff e1 

raop_rtp_mirror SPS NAL size = 18
raop_rtp_mirror h264 Sequence Parameter Set:
27 64 00 1f ac 13 14 50 20 02 27 9e 59 b8 08 08 
08 10 

raop_rtp_mirror PPS NAL size = 4
raop_rtp_mirror h264 Picture Parameter Set:
28 ee 3c b0 

remainder size = 4
remainder of SPS+PPS packet:
02 00 00 00 

video renderer paused
raop_rtp video: now = 1713524235.164383, ntp = 1713524235.230250, latency = -0.065866, ts = 368510.017368, 00 10 00 00 
video renderer resumed
Begin streaming to GStreamer video pipeline
Looking for X11 UxPlay Window, attempt 1
raop_rtp video: now = 1713524235.178092, ntp = 1713524235.280400, latency = -0.102308, ts = 368510.067518, 00 00 00 00 
video renderer resumed
Looking for X11 UxPlay Window, attempt 2
raop_rtp video: now = 1713524235.243915, ntp = 1713524235.313834, latency = -0.069919, ts = 368510.100952, 00 00 00 00 
video renderer resumed
Looking for X11 UxPlay Window, attempt 3
raop_rtp video: now = 1713524235.248762, ntp = 1713524235.347267, latency = -0.098505, ts = 368510.134385, 00 00 00 00 
video renderer resumed
Looking for X11 UxPlay Window, attempt 4
raop_rtp video: now = 1713524235.283732, ntp = 1713524235.380701, latency = -0.096969, ts = 368510.167819, 00 00 00 00 
video renderer resumed
Looking for X11 UxPlay Window, attempt 5
X11 UxPlay Window not found in 5 search attempts
raop_rtp video: now = 1713524235.319073, ntp = 1713524235.414135, latency = -0.095061, ts = 368510.201253, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.345266, ntp = 1713524235.447568, latency = -0.102302, ts = 368510.234686, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.406564, ntp = 1713524235.481002, latency = -0.074438, ts = 368510.268120, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.441861, ntp = 1713524235.514436, latency = -0.072574, ts = 368510.301554, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.450435, ntp = 1713524235.547869, latency = -0.097434, ts = 368510.334988, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.479780, ntp = 1713524235.581303, latency = -0.101523, ts = 368510.368421, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.555121, ntp = 1713524235.631454, latency = -0.076332, ts = 368510.418572, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.596719, ntp = 1713524235.664787, latency = -0.068068, ts = 368510.451905, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.650973, ntp = 1713524235.698120, latency = -0.047147, ts = 368510.485238, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.663774, ntp = 1713524235.731454, latency = -0.067679, ts = 368510.518572, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.669822, ntp = 1713524235.765188, latency = -0.095367, ts = 368510.552306, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.738571, ntp = 1713524235.798522, latency = -0.059951, ts = 368510.585640, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.780137, ntp = 1713524235.831855, latency = -0.051718, ts = 368510.618973, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.803415, ntp = 1713524235.865188, latency = -0.061774, ts = 368510.652306, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.842826, ntp = 1713524235.898522, latency = -0.055695, ts = 368510.685640, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.869987, ntp = 1713524235.931855, latency = -0.061868, ts = 368510.718973, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.983872, ntp = 1713524235.965188, latency = 0.018684, ts = 368510.752306, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.983889, ntp = 1713524235.998522, latency = -0.014632, ts = 368510.785640, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524235.983936, ntp = 1713524236.031855, latency = -0.047919, ts = 368510.818973, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.004252, ntp = 1713524236.065188, latency = -0.060937, ts = 368510.852306, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.036774, ntp = 1713524236.098522, latency = -0.061747, ts = 368510.885640, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.070198, ntp = 1713524236.131855, latency = -0.061657, ts = 368510.918973, 00 00 00 00 
video renderer resumed

Received video streaming performance info packet from client: payload_size 25194 header 05 00 00 00  ts_raw = 0
raop_rtp video: now = 1713524236.111733, ntp = 1713524236.165188, latency = -0.053455, ts = 368510.952306, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.162326, ntp = 1713524236.216543, latency = -0.054217, ts = 368511.003661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.183444, ntp = 1713524236.249876, latency = -0.066432, ts = 368511.036994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.216070, ntp = 1713524236.283210, latency = -0.067140, ts = 368511.070328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.255239, ntp = 1713524236.316543, latency = -0.061304, ts = 368511.103661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.301585, ntp = 1713524236.349876, latency = -0.048291, ts = 368511.136994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.316530, ntp = 1713524236.383209, latency = -0.066680, ts = 368511.170328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.350887, ntp = 1713524236.416543, latency = -0.065656, ts = 368511.203661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.381763, ntp = 1713524236.449876, latency = -0.068113, ts = 368511.236994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.464934, ntp = 1713524236.483209, latency = -0.018275, ts = 368511.270328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.464953, ntp = 1713524236.516543, latency = -0.051590, ts = 368511.303661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.483094, ntp = 1713524236.549876, latency = -0.066782, ts = 368511.336994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.516324, ntp = 1713524236.583210, latency = -0.066886, ts = 368511.370328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.556827, ntp = 1713524236.616543, latency = -0.059716, ts = 368511.403661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.582620, ntp = 1713524236.649876, latency = -0.067256, ts = 368511.436994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.617830, ntp = 1713524236.683209, latency = -0.065380, ts = 368511.470328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.677664, ntp = 1713524236.716543, latency = -0.038879, ts = 368511.503661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.683666, ntp = 1713524236.749876, latency = -0.066211, ts = 368511.536994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.743129, ntp = 1713524236.783210, latency = -0.040081, ts = 368511.570328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.748373, ntp = 1713524236.816543, latency = -0.068170, ts = 368511.603661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.795190, ntp = 1713524236.849876, latency = -0.054686, ts = 368511.636994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.819438, ntp = 1713524236.883209, latency = -0.063772, ts = 368511.670328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.849779, ntp = 1713524236.916543, latency = -0.066764, ts = 368511.703661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.883436, ntp = 1713524236.949876, latency = -0.066440, ts = 368511.736994, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524236.916635, ntp = 1713524236.983209, latency = -0.066574, ts = 368511.770328, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.045600, ntp = 1713524237.016543, latency = 0.029057, ts = 368511.803661, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.045617, ntp = 1713524237.052385, latency = -0.006767, ts = 368511.839503, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.045621, ntp = 1713524237.085818, latency = -0.040197, ts = 368511.872936, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.045625, ntp = 1713524237.119252, latency = -0.073627, ts = 368511.906370, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.059937, ntp = 1713524237.152685, latency = -0.092748, ts = 368511.939803, 00 00 00 00 
video renderer resumed
httpd receiving on socket 451
conn_request

POST /feedback RTSP/1.0
CSeq: 8
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

Handling request POST with URL /feedback
raop_handler_feedback

RTSP/1.0 200 OK 
CSeq: 8 
Server: AirTunes/220.68 

raop_rtp video: now = 1713524237.087949, ntp = 1713524237.186119, latency = -0.098170, ts = 368511.973237, 00 00 00 00 
video renderer resumed

Received video streaming performance info packet from client: payload_size 25376 header 05 00 00 00  ts_raw = 0
raop_rtp video: now = 1713524237.122302, ntp = 1713524237.219553, latency = -0.097251, ts = 368512.006671, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.171649, ntp = 1713524237.252986, latency = -0.081337, ts = 368512.040104, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.187038, ntp = 1713524237.286420, latency = -0.099382, ts = 368512.073538, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.220354, ntp = 1713524237.319853, latency = -0.099500, ts = 368512.106971, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.273641, ntp = 1713524237.353287, latency = -0.079646, ts = 368512.140405, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.286623, ntp = 1713524237.386720, latency = -0.100097, ts = 368512.173839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.355850, ntp = 1713524237.420054, latency = -0.064203, ts = 368512.207172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.385901, ntp = 1713524237.453387, latency = -0.067486, ts = 368512.240505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.421976, ntp = 1713524237.486721, latency = -0.064745, ts = 368512.273839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.452992, ntp = 1713524237.520054, latency = -0.067062, ts = 368512.307172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.497069, ntp = 1713524237.553387, latency = -0.056318, ts = 368512.340505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.518887, ntp = 1713524237.586720, latency = -0.067834, ts = 368512.373839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.552785, ntp = 1713524237.620054, latency = -0.067269, ts = 368512.407172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.588443, ntp = 1713524237.653387, latency = -0.064945, ts = 368512.440505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.643038, ntp = 1713524237.686721, latency = -0.043683, ts = 368512.473839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.652528, ntp = 1713524237.720054, latency = -0.067526, ts = 368512.507172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.688409, ntp = 1713524237.753387, latency = -0.064979, ts = 368512.540505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.720196, ntp = 1713524237.786721, latency = -0.066525, ts = 368512.573839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.753203, ntp = 1713524237.820054, latency = -0.066851, ts = 368512.607172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.801652, ntp = 1713524237.853387, latency = -0.051736, ts = 368512.640505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.822601, ntp = 1713524237.886720, latency = -0.064120, ts = 368512.673839, 00 00 00 00 
video renderer resumed

raop_ntp send time type_t=82 packetlen = 32, now = 1713524237.840620
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 cc cc 8d d7 32 d5 77 

raop_rtp video: now = 1713524237.853511, ntp = 1713524237.920054, latency = -0.066543, ts = 368512.707172, 00 00 00 00 
video renderer resumed
raop_ntp receive time type_t=83 packetlen = 32, now = 1713524237.861323 t1 = 368512.643608, t2 = 368512.643689
80 d3 00 07 00 00 00 00 e9 cc cc 8d d7 32 d5 77 
83 b0 1e 00 a4 c3 78 d7 83 b0 1e 00 a4 c8 ce 16 

raop_ntp sync correction = 0
raop_rtp video: now = 1713524237.886733, ntp = 1713524237.953387, latency = -0.066655, ts = 368512.740505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.939989, ntp = 1713524237.986721, latency = -0.046732, ts = 368512.773839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.952928, ntp = 1713524238.020054, latency = -0.067126, ts = 368512.807172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524237.986687, ntp = 1713524238.053387, latency = -0.066700, ts = 368512.840505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.078110, ntp = 1713524238.086720, latency = -0.008611, ts = 368512.873839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.078138, ntp = 1713524238.120054, latency = -0.041916, ts = 368512.907172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.086195, ntp = 1713524238.153387, latency = -0.067192, ts = 368512.940505, 00 00 00 00 
video renderer resumed

Received video streaming performance info packet from client: payload_size 25372 header 05 00 00 00  ts_raw = 0
raop_rtp video: now = 1713524238.134104, ntp = 1713524238.186721, latency = -0.052616, ts = 368512.973839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.153080, ntp = 1713524238.220054, latency = -0.066974, ts = 368513.007172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.186284, ntp = 1713524238.253387, latency = -0.067103, ts = 368513.040505, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.244699, ntp = 1713524238.286721, latency = -0.042022, ts = 368513.073839, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.254303, ntp = 1713524238.320054, latency = -0.065751, ts = 368513.107172, 00 00 00 00 
video renderer resumed
raop_rtp video: now = 1713524238.296658, ntp = 1713524238.353387, latency = -0.056729, ts = 368513.140505, 00 00 00 00 
video renderer resumed

Received video streaming performance info packet from client: payload_size 25372 header 05 00 00 00  ts_raw = 0
httpd receiving on socket 451
conn_request

POST /feedback RTSP/1.0
CSeq: 9
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

Handling request POST with URL /feedback
raop_handler_feedback

RTSP/1.0 200 OK 
CSeq: 9 
Server: AirTunes/220.68 

Received video streaming performance info packet from client: payload_size 25364 header 05 00 00 00  ts_raw = 0

raop_ntp send time type_t=82 packetlen = 32, now = 1713524240.861628
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 cc cc 90 dc 93 a5 ca 

raop_ntp receive time type_t=83 packetlen = 32, now = 1713524241.050085 t1 = 368515.831953, t2 = 368515.832054
80 d3 00 07 00 00 00 00 e9 cc cc 90 dc 93 a5 ca 
83 b0 1e 03 d4 fa e6 df 83 b0 1e 03 d5 01 85 5f 

raop_ntp sync correction = 0
raop_rtp video: now = 1713524241.067914, ntp = 1713524241.164725, latency = -0.096811, ts = 368515.951843, 00 00 00 00 
video renderer resumed
httpd receiving on socket 451
conn_request

POST /feedback RTSP/1.0
CSeq: 10
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

Handling request POST with URL /feedback
raop_handler_feedback

RTSP/1.0 200 OK 
CSeq: 10 
Server: AirTunes/220.68 

Received video streaming performance info packet from client: payload_size 25364 header 05 00 00 00  ts_raw = 0
raop_rtp video: now = 1713524241.248085, ntp = 1713524241.214393, latency = 0.033691, ts = 368516.001512, 00 00 00 00 
video renderer resumed
raop_rtp_mirror tcp socket is closed, got 0 bytes of 128 byte header
httpd receiving on socket 451
conn_request

TEARDOWN rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
Content-Length: 69
Content-Type: application/x-apple-binary-plist
CSeq: 11
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>streams</key>
    <array>
        <dict>
            <key>type</key>
            <integer>110</integer>
        </dict>
    </array>
</dict>
</plist>

Handling request TEARDOWN with URL rtsp://192.168.0.110/17373466028610701476
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>streams</key>
    <array>
        <dict>
            <key>type</key>
            <integer>110</integer>
        </dict>
    </array>
</dict>
</plist>

TEARDOWN request,  96=0, 110=1
raop_rtp_mirror->running is no longer true
raop_rtp_mirror exiting TCP thread

RTSP/1.0 200 OK 
CSeq: 11 
Server: AirTunes/220.68 
Connection: close 

httpd receiving on socket 451
conn_request

TEARDOWN rtsp://192.168.0.110/17373466028610701476 RTSP/1.0
Content-Length: 42
Content-Type: application/x-apple-binary-plist
CSeq: 12
DACP-ID: 9C592E9DE4847020
Active-Remote: 3501575261
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict/>
</plist>

Handling request TEARDOWN with URL rtsp://192.168.0.110/17373466028610701476
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict/>
</plist>

TEARDOWN request,  96=0, 110=0

RTSP/1.0 200 OK 
CSeq: 12 
Server: AirTunes/220.68 
Connection: close 

httpd receiving on socket 451
Connection closed for socket 451
Destroying connection
Open connections: 1
raop_ntp stopping time thread
raop_ntp exiting thread
raop_ntp stopped time thread
httpd receiving on socket 453
Connection closed for socket 453
Destroying connection
Open connections: 0
GStreamer video pipeline will be:
"appsrc name=video_source ! queue ! h264parse ! decodebin ! videoconvert ! autovideosink name=video_sink sync=true"
Initialized GStreamer video renderer
Stopping...
Exiting HTTP thread

fduncanh commented 5 months ago

Yes this may be an issue connected to

X11 UxPlay Window not found in 5 search attempts

(or it may be something else.)

in line 33 ofUxPlay/renderers/video_renderer_gstreamer.c

define MAX_X11_SEARCH_ATTEMPTS 5 /should be less than 256 /

change "5" to "255" and recompile. Does this fix your problem?

if not, do

export GST_DEBUG=3

before running uxplay to see gstreamer debug messages.

fduncanh commented 5 months ago

The X11 search is to do something that is only needed when using gstreamer's ximagesink or xvimagesink videosinks.

(but there was no obvious way to know if autovideosink had chosen them). The search is abandoned after 5 attempts on the assumption that a different videosink is being used. (so an X11 handle will never be found).

feuera commented 5 months ago

define MAX_X11_SEARCH_ATTEMPTS 5 /should be less than 256 /

change "5" to "255" and recompile. Does this fix your problem?

did not solve the problem

export GST_DEBUG=3

./uxplay          
UxPlay 1.68: An Open-Source AirPlay mirroring and audio-streaming server.
0:00:00.052051211 731312 0x7838b4000e30 FIXME                default gstutils.c:4088:gst_element_decorate_stream_id_internal:<video_source> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
using system MAC address 00:93:37:7a:31:cc
Initialized server socket(s)
Accepted IPv6 client on socket 452
Local: fe80:0000:0000:0000:1ea6:c4fa:4ac8:9af3
Remote: fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
connection request from Meins (iPhone13,1) with deviceID = FC:66:CF:DF:2E:52

Client identified as User-Agent: AirPlay/760.20.1
client is using IPV6 (untested!)
Accepted IPv6 client on socket 454
Local: fe80:0000:0000:0000:1ea6:c4fa:4ac8:9af3
Remote: fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
raop_rtp_mirror starting mirroring
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
376365.520149 ntp_time
1713540576.977341 base_time

using GST_DEBUG=4 starting:

./uxplay          
UxPlay 1.68: An Open-Source AirPlay mirroring and audio-streaming server.
0:00:00.000040067 734154 0x569a1759d390 INFO                GST_INIT gst.c:574:init_pre: Initializing GStreamer Core Library version 1.24.1
0:00:00.000050848 734154 0x569a1759d390 INFO                GST_INIT gst.c:575:init_pre: Using library installed in /usr/lib
0:00:00.000054112 734154 0x569a1759d390 INFO                GST_INIT gst.c:593:init_pre: Linux g9studio 6.8.7-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 17 Apr 2024 15:20:28 +0000 x86_64
0:00:00.000157771 734154 0x569a1759d390 INFO                GST_INIT gstmessage.c:129:_priv_gst_message_initialize: init messages
0:00:00.000290633 734154 0x569a1759d390 INFO                GST_INIT gstcontext.c:86:_priv_gst_context_initialize: init contexts
0:00:00.000351266 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:328:_priv_gst_plugin_initialize: registering 0 static plugins
0:00:00.000372650 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:236:gst_plugin_register_static: registered static plugin "staticelements"
0:00:00.000376068 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:238:gst_plugin_register_static: added static plugin "staticelements", result: 1
0:00:00.000388220 734154 0x569a1759d390 INFO            GST_REGISTRY gstregistry.c:1918:ensure_current_registry: reading registry cache: /home/andi/.cache/gstreamer-1.0/registry.x86_64.bin
0:00:00.005243098 734154 0x569a1759d390 INFO            GST_REGISTRY gstregistrybinary.c:683:priv_gst_registry_binary_read_cache: loaded /home/andi/.cache/gstreamer-1.0/registry.x86_64.bin in 0.004848 seconds
0:00:00.005294603 734154 0x569a1759d390 INFO            GST_REGISTRY gstregistry.c:1785:scan_and_update_registry: Validating plugins from registry cache: /home/andi/.cache/gstreamer-1.0/registry.x86_64.bin
0:00:00.006572452 734154 0x569a1759d390 INFO            GST_REGISTRY gstregistry.c:1877:scan_and_update_registry: Registry cache has not changed
0:00:00.006576349 734154 0x569a1759d390 INFO            GST_REGISTRY gstregistry.c:1953:ensure_current_registry: registry reading and updating done
0:00:00.006579324 734154 0x569a1759d390 INFO                GST_INIT gst.c:807:init_post: GLib runtime version: 2.80.0
0:00:00.006581686 734154 0x569a1759d390 INFO                GST_INIT gst.c:809:init_post: GLib headers version: 2.80.0
0:00:00.006583166 734154 0x569a1759d390 INFO                GST_INIT gst.c:811:init_post: initialized GStreamer successfully
0:00:00.006689707 734154 0x569a1759d390 INFO            GST_PIPELINE gstparse.c:344:gst_parse_launch_full: parsing pipeline description 'appsrc name=audio_source ! queue ! avdec_aac ! audioconvert ! audioresample ! volume name=volume ! level ! autoaudiosink sync=true'
0:00:00.006777032 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstapp.so" loaded
0:00:00.006820089 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "appsrc"
0:00:00.006826293 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSrc@0x569a17851820> adding pad 'src'
0:00:00.007028359 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstcoreelements.so" loaded
0:00:00.007047005 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "queue"
0:00:00.007052957 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17876930> adding pad 'sink'
0:00:00.007082072 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17876930> adding pad 'src'
0:00:00.028888514 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_avs
0:00:00.028928143 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_bfstm
0:00:00.028935783 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_brstm
0:00:00.028945365 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_daud
0:00:00.028951163 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_dsf
0:00:00.028958003 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_ea
0:00:00.028964980 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_4xm
0:00:00.028972962 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_gxf
0:00:00.028978872 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_idcin
0:00:00.028983780 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_iff
0:00:00.028989517 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_ipmovie
0:00:00.028998258 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_mm
0:00:00.029003008 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_mmf
0:00:00.029013373 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_nsv
0:00:00.029017995 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_nut
0:00:00.029031134 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_film_cpk
0:00:00.029037660 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_smk
0:00:00.029042617 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_sol
0:00:00.029048486 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_psxstr
0:00:00.029057487 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_vmd
0:00:00.029064270 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_wc3movie
0:00:00.029069263 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_wsaud
0:00:00.029074086 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_wsvqa
0:00:00.029080389 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_xwma
0:00:00.029085473 734154 0x569a1759d390 INFO            GST_TYPEFIND gsttypefind.c:72:gst_type_find_register: registering typefind function for avtype_yuv4mpegpipe
0:00:00.029208067 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstlibav.so" loaded
0:00:00.029252896 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "avdec_aac"
0:00:00.029260021 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x569a17929800> adding pad 'sink'
0:00:00.029264578 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x569a17929800> adding pad 'src'
0:00:00.029441571 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstaudioconvert.so" loaded
0:00:00.029477333 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "audioconvert"
0:00:00.029482840 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a17932c20> adding pad 'sink'
0:00:00.029486882 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a17932c20> adding pad 'src'
0:00:00.029598414 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstaudioresample.so" loaded
0:00:00.029625226 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "audioresample"
0:00:00.029628692 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a179364c0> adding pad 'sink'
0:00:00.029631608 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a179364c0> adding pad 'src'
0:00:00.029735693 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstvolume.so" loaded
0:00:00.029757809 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "volume"
0:00:00.029761485 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a17928620> adding pad 'sink'
0:00:00.029764583 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a17928620> adding pad 'src'
0:00:00.029847978 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstlevel.so" loaded
0:00:00.029863660 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "level"
0:00:00.029866819 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1793c100> adding pad 'sink'
0:00:00.029869726 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1793c100> adding pad 'src'
0:00:00.029956451 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstautodetect.so" loaded
0:00:00.029966844 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "autoaudiosink"
0:00:00.029978971 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<autoaudiosink0> adding pad 'sink'
0:00:00.030007977 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "fakesink"
0:00:00.030012933 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSink@0x569a17941de0> adding pad 'sink'
0:00:00.030025879 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad fake-audio-sink:sink
0:00:00.030029865 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link sink:proxypad0 and fake-audio-sink:sink
0:00:00.030032929 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked sink:proxypad0 and fake-audio-sink:sink, successful
0:00:00.030035221 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030042578 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "pipeline"
0:00:00.030073317 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAppSrc named audio_source to some pad of GstQueue named queue0 (0/0) with caps "(NULL)"
0:00:00.030077630 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audio_source:(any) to element queue0:(any)
0:00:00.030081119 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audio_source:src and queue0:sink
0:00:00.030087092 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue0:src> pad has no peer
0:00:00.030093676 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audio_source and queue0 in same bin, no need for ghost pads
0:00:00.030099223 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audio_source:src and queue0:sink
0:00:00.030103327 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue0:src> pad has no peer
0:00:00.030106595 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audio_source:src and queue0:sink, successful
0:00:00.030108413 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030110578 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audio_source:src> Received event on flushing pad. Discarding
0:00:00.030116523 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstQueue named queue0 to some pad of avdec_aac named avdec_aac0 (0/0) with caps "(NULL)"
0:00:00.030124882 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element queue0:(any) to element avdec_aac0:(any)
0:00:00.030127795 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link queue0:src and avdec_aac0:sink
0:00:00.030133783 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_aac0:src> pad has no peer
0:00:00.030142385 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: queue0 and avdec_aac0 in same bin, no need for ghost pads
0:00:00.030145978 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link queue0:src and avdec_aac0:sink
0:00:00.030149532 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_aac0:src> pad has no peer
0:00:00.030154599 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked queue0:src and avdec_aac0:sink, successful
0:00:00.030156898 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030159313 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<queue0:src> Received event on flushing pad. Discarding
0:00:00.030164269 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of avdec_aac named avdec_aac0 to some pad of GstAudioConvert named audioconvert0 (0/0) with caps "(NULL)"
0:00:00.030168339 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element avdec_aac0:(any) to element audioconvert0:(any)
0:00:00.030171490 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link avdec_aac0:src and audioconvert0:sink
0:00:00.030174969 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioconvert0:src> pad has no peer
0:00:00.030184011 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030196882 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: avdec_aac0 and audioconvert0 in same bin, no need for ghost pads
0:00:00.030200269 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link avdec_aac0:src and audioconvert0:sink
0:00:00.030203128 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioconvert0:src> pad has no peer
0:00:00.030208233 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030217704 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked avdec_aac0:src and audioconvert0:sink, successful
0:00:00.030220093 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030222319 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<avdec_aac0:src> Received event on flushing pad. Discarding
0:00:00.030229021 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAudioConvert named audioconvert0 to some pad of GstAudioResample named audioresample0 (0/0) with caps "(NULL)"
0:00:00.030233277 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audioconvert0:(any) to element audioresample0:(any)
0:00:00.030236422 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audioconvert0:src and audioresample0:sink
0:00:00.030242299 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030250744 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioresample0:src> pad has no peer
0:00:00.030263492 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audioconvert0 and audioresample0 in same bin, no need for ghost pads
0:00:00.030266822 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audioconvert0:src and audioresample0:sink
0:00:00.030271901 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030277929 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioresample0:src> pad has no peer
0:00:00.030290428 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audioconvert0:src and audioresample0:sink, successful
0:00:00.030292611 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030294953 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audioconvert0:src> Received event on flushing pad. Discarding
0:00:00.030300332 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAudioResample named audioresample0 to some pad of GstVolume named volume (0/0) with caps "(NULL)"
0:00:00.030304105 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audioresample0:(any) to element volume:(any)
0:00:00.030307230 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audioresample0:src and volume:sink
0:00:00.030310214 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<volume:src> pad has no peer
0:00:00.030315159 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audioresample0 and volume in same bin, no need for ghost pads
0:00:00.030318306 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audioresample0:src and volume:sink
0:00:00.030321126 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<volume:src> pad has no peer
0:00:00.030325699 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audioresample0:src and volume:sink, successful
0:00:00.030327931 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030330195 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audioresample0:src> Received event on flushing pad. Discarding
0:00:00.030334517 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstVolume named volume to some pad of GstLevel named level0 (0/0) with caps "(NULL)"
0:00:00.030339013 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element volume:(any) to element level0:(any)
0:00:00.030342040 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link volume:src and level0:sink
0:00:00.030351586 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<level0:src> pad has no peer
0:00:00.030357032 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: volume and level0 in same bin, no need for ghost pads
0:00:00.030360276 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link volume:src and level0:sink
0:00:00.030369076 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<level0:src> pad has no peer
0:00:00.030374231 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked volume:src and level0:sink, successful
0:00:00.030376401 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030378717 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<volume:src> Received event on flushing pad. Discarding
0:00:00.030383690 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstLevel named level0 to some pad of GstAutoAudioSink named autoaudiosink0 (0/0) with caps "(NULL)"
0:00:00.030386953 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element level0:(any) to element autoaudiosink0:(any)
0:00:00.030389955 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link level0:src and autoaudiosink0:sink
0:00:00.030405289 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: level0 and autoaudiosink0 in same bin, no need for ghost pads
0:00:00.030408616 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link level0:src and autoaudiosink0:sink
0:00:00.030421739 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked level0:src and autoaudiosink0:sink, successful
0:00:00.030423998 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030426191 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<level0:src> Received event on flushing pad. Discarding
0:00:00.030433397 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline0]: looking up child element audio_source
0:00:00.030438654 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline0]: looking up child element volume
0:00:00.030457388 734154 0x569a1759d390 INFO            GST_PIPELINE gstparse.c:344:gst_parse_launch_full: parsing pipeline description 'appsrc name=audio_source ! queue ! avdec_alac ! audioconvert ! audioresample ! volume name=volume ! level ! autoaudiosink sync=false'
0:00:00.030462941 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "appsrc"
0:00:00.030468091 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSrc@0x569a17944070> adding pad 'src'
0:00:00.030473101 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "queue"
0:00:00.030479240 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17944580> adding pad 'sink'
0:00:00.030483865 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17944580> adding pad 'src'
0:00:00.030502417 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "avdec_alac"
0:00:00.030507202 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x569a17947810> adding pad 'sink'
0:00:00.030510622 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstAudioDecoder@0x569a17947810> adding pad 'src'
0:00:00.030523145 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "audioconvert"
0:00:00.030527083 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794b150> adding pad 'sink'
0:00:00.030530553 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794b150> adding pad 'src'
0:00:00.030535557 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "audioresample"
0:00:00.030539186 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794c140> adding pad 'sink'
0:00:00.030542539 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794c140> adding pad 'src'
0:00:00.030547154 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "volume"
0:00:00.030551946 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794d040> adding pad 'sink'
0:00:00.030555147 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794d040> adding pad 'src'
0:00:00.030558925 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "level"
0:00:00.030563128 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794de90> adding pad 'sink'
0:00:00.030566320 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1794de90> adding pad 'src'
0:00:00.030571059 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "autoaudiosink"
0:00:00.030579016 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<autoaudiosink1> adding pad 'sink'
0:00:00.030582247 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "fakesink"
0:00:00.030586895 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSink@0x569a1794fd60> adding pad 'sink'
0:00:00.030592710 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad fake-audio-sink:sink
0:00:00.030595979 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link sink:proxypad1 and fake-audio-sink:sink
0:00:00.030598936 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked sink:proxypad1 and fake-audio-sink:sink, successful
0:00:00.030601211 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030605947 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "pipeline"
0:00:00.030625947 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAppSrc named audio_source to some pad of GstQueue named queue1 (0/0) with caps "(NULL)"
0:00:00.030632166 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audio_source:(any) to element queue1:(any)
0:00:00.030635245 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audio_source:src and queue1:sink
0:00:00.030638700 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue1:src> pad has no peer
0:00:00.030642061 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audio_source and queue1 in same bin, no need for ghost pads
0:00:00.030645479 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audio_source:src and queue1:sink
0:00:00.030648261 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue1:src> pad has no peer
0:00:00.030651454 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audio_source:src and queue1:sink, successful
0:00:00.030653571 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030655918 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audio_source:src> Received event on flushing pad. Discarding
0:00:00.030660759 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstQueue named queue1 to some pad of avdec_alac named avdec_alac0 (0/0) with caps "(NULL)"
0:00:00.030665648 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element queue1:(any) to element avdec_alac0:(any)
0:00:00.030668646 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link queue1:src and avdec_alac0:sink
0:00:00.030675408 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_alac0:src> pad has no peer
0:00:00.030679676 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: queue1 and avdec_alac0 in same bin, no need for ghost pads
0:00:00.030682766 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link queue1:src and avdec_alac0:sink
0:00:00.030686009 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<avdec_alac0:src> pad has no peer
0:00:00.030689717 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked queue1:src and avdec_alac0:sink, successful
0:00:00.030691898 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030694150 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<queue1:src> Received event on flushing pad. Discarding
0:00:00.030698539 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of avdec_alac named avdec_alac0 to some pad of GstAudioConvert named audioconvert1 (0/0) with caps "(NULL)"
0:00:00.030702407 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element avdec_alac0:(any) to element audioconvert1:(any)
0:00:00.030705364 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link avdec_alac0:src and audioconvert1:sink
0:00:00.030708330 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioconvert1:src> pad has no peer
0:00:00.030714174 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030725428 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: avdec_alac0 and audioconvert1 in same bin, no need for ghost pads
0:00:00.030728732 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link avdec_alac0:src and audioconvert1:sink
0:00:00.030731682 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioconvert1:src> pad has no peer
0:00:00.030736593 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030745307 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked avdec_alac0:src and audioconvert1:sink, successful
0:00:00.030747546 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030749889 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<avdec_alac0:src> Received event on flushing pad. Discarding
0:00:00.030755737 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAudioConvert named audioconvert1 to some pad of GstAudioResample named audioresample1 (0/0) with caps "(NULL)"
0:00:00.030759954 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audioconvert1:(any) to element audioresample1:(any)
0:00:00.030763024 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audioconvert1:src and audioresample1:sink
0:00:00.030769716 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030777732 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioresample1:src> pad has no peer
0:00:00.030788684 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audioconvert1 and audioresample1 in same bin, no need for ghost pads
0:00:00.030791831 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audioconvert1:src and audioresample1:sink
0:00:00.030798069 734154 0x569a1759d390 INFO               structure gststructure.c:2956:gst_structure_get_valist: Expected field 'channel-mask' in structure: audio/x-raw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 2147483647 ];
0:00:00.030804769 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<audioresample1:src> pad has no peer
0:00:00.030816394 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audioconvert1:src and audioresample1:sink, successful
0:00:00.030818584 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030821262 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audioconvert1:src> Received event on flushing pad. Discarding
0:00:00.030827255 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAudioResample named audioresample1 to some pad of GstVolume named volume (0/0) with caps "(NULL)"
0:00:00.030830550 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element audioresample1:(any) to element volume:(any)
0:00:00.030833600 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link audioresample1:src and volume:sink
0:00:00.030836453 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<volume:src> pad has no peer
0:00:00.030840998 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: audioresample1 and volume in same bin, no need for ghost pads
0:00:00.030844130 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link audioresample1:src and volume:sink
0:00:00.030846925 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<volume:src> pad has no peer
0:00:00.030851345 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked audioresample1:src and volume:sink, successful
0:00:00.030853522 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030855694 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<audioresample1:src> Received event on flushing pad. Discarding
0:00:00.030860472 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstVolume named volume to some pad of GstLevel named level1 (0/0) with caps "(NULL)"
0:00:00.030864445 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element volume:(any) to element level1:(any)
0:00:00.030867390 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link volume:src and level1:sink
0:00:00.030876664 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<level1:src> pad has no peer
0:00:00.030881891 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: volume and level1 in same bin, no need for ghost pads
0:00:00.030885375 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link volume:src and level1:sink
0:00:00.030893786 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<level1:src> pad has no peer
0:00:00.030898898 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked volume:src and level1:sink, successful
0:00:00.030900995 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030903292 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<volume:src> Received event on flushing pad. Discarding
0:00:00.030907537 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstLevel named level1 to some pad of GstAutoAudioSink named autoaudiosink1 (0/0) with caps "(NULL)"
0:00:00.030910856 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element level1:(any) to element autoaudiosink1:(any)
0:00:00.030913824 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link level1:src and autoaudiosink1:sink
0:00:00.030926930 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: level1 and autoaudiosink1 in same bin, no need for ghost pads
0:00:00.030929953 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link level1:src and autoaudiosink1:sink
0:00:00.030942340 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked level1:src and autoaudiosink1:sink, successful
0:00:00.030944454 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.030946578 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<level1:src> Received event on flushing pad. Discarding
0:00:00.030951763 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline1]: looking up child element audio_source
0:00:00.030956431 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline1]: looking up child element volume
0:00:00.030971805 734154 0x569a1759d390 INFO            GST_PIPELINE gstparse.c:344:gst_parse_launch_full: parsing pipeline description 'appsrc name=video_source ! queue ! h264parse ! decodebin ! videoconvert ! autovideosink name=video_sink sync=true'
0:00:00.030976981 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "appsrc"
0:00:00.030981402 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSrc@0x569a17951d80> adding pad 'src'
0:00:00.030985551 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "queue"
0:00:00.030990695 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17952290> adding pad 'sink'
0:00:00.030995022 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstQueue@0x569a17952290> adding pad 'src'
0:00:00.031256619 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstvideoparsersbad.so" loaded
0:00:00.031294616 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "h264parse"
0:00:00.031316114 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x569a179574a0> adding pad 'sink'
0:00:00.031323050 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x569a179574a0> adding pad 'src'
0:00:00.031329631 734154 0x569a1759d390 INFO               baseparse gstbaseparse.c:4067:gst_base_parse_set_pts_interpolation:<GstH264Parse@0x569a179574a0> PTS interpolation: no
0:00:00.031332100 734154 0x569a1759d390 INFO               baseparse gstbaseparse.c:4085:gst_base_parse_set_infer_ts:<GstH264Parse@0x569a179574a0> TS inferring: no
0:00:00.031612042 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstplayback.so" loaded
0:00:00.031651567 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "decodebin"
0:00:00.031665869 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "typefind"
0:00:00.031671769 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstTypeFindElement@0x569a17961300> adding pad 'sink'
0:00:00.031678451 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstTypeFindElement@0x569a17961300> adding pad 'src'
0:00:00.031688342 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad typefind:sink
0:00:00.031698458 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link sink:proxypad2 and typefind:sink
0:00:00.031704891 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked sink:proxypad2 and typefind:sink, successful
0:00:00.031707064 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.031712685 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstDecodeBin@0x569a179602e0> adding pad 'sink'
0:00:00.031847870 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstvideoconvertscale.so" loaded
0:00:00.031918959 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "videoconvert"
0:00:00.031923872 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1796ba50> adding pad 'sink'
0:00:00.031928166 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x569a1796ba50> adding pad 'src'
0:00:00.031940607 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "autovideosink"
0:00:00.031948824 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<video_sink> adding pad 'sink'
0:00:00.031952020 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "fakesink"
0:00:00.031956978 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSink@0x569a1796fef0> adding pad 'sink'
0:00:00.031964126 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad fake-video-sink:sink
0:00:00.031967492 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link sink:proxypad3 and fake-video-sink:sink
0:00:00.031970664 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked sink:proxypad3 and fake-video-sink:sink, successful
0:00:00.031972998 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.031978436 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "pipeline"
0:00:00.032001496 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstAppSrc named video_source to some pad of GstQueue named queue2 (0/0) with caps "(NULL)"
0:00:00.032006677 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element video_source:(any) to element queue2:(any)
0:00:00.032010115 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link video_source:src and queue2:sink
0:00:00.032015151 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue2:src> pad has no peer
0:00:00.032019407 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: video_source and queue2 in same bin, no need for ghost pads
0:00:00.032023563 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link video_source:src and queue2:sink
0:00:00.032026735 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<queue2:src> pad has no peer
0:00:00.032030338 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked video_source:src and queue2:sink, successful
0:00:00.032032607 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.032035087 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<video_source:src> Received event on flushing pad. Discarding
0:00:00.032041002 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstQueue named queue2 to some pad of GstH264Parse named h264parse0 (0/0) with caps "(NULL)"
0:00:00.032046252 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element queue2:(any) to element h264parse0:(any)
0:00:00.032054252 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link queue2:src and h264parse0:sink
0:00:00.032059440 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<h264parse0:src> pad has no peer
0:00:00.032063811 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: queue2 and h264parse0 in same bin, no need for ghost pads
0:00:00.032066550 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link queue2:src and h264parse0:sink
0:00:00.032069378 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<h264parse0:src> pad has no peer
0:00:00.032072359 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked queue2:src and h264parse0:sink, successful
0:00:00.032074055 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.032075869 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<queue2:src> Received event on flushing pad. Discarding
0:00:00.032080476 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstH264Parse named h264parse0 to some pad of GstDecodeBin named decodebin0 (0/0) with caps "(NULL)"
0:00:00.032083429 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element h264parse0:(any) to element decodebin0:(any)
0:00:00.032086128 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link h264parse0:src and decodebin0:sink
0:00:00.032090782 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: h264parse0 and decodebin0 in same bin, no need for ghost pads
0:00:00.032093409 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link h264parse0:src and decodebin0:sink
0:00:00.032096961 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked h264parse0:src and decodebin0:sink, successful
0:00:00.032098560 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.032100287 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<h264parse0:src> Received event on flushing pad. Discarding
0:00:00.032104100 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstDecodeBin named decodebin0 to some pad of GstVideoConvert named videoconvert0 (0/0) with caps "(NULL)"
0:00:00.032106950 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element decodebin0:(any) to element videoconvert0:(any)
0:00:00.032109633 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert0:src> pad has no peer
0:00:00.032399014 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1013:gst_element_get_static_pad: no such pad 'src_%u' in element "decodebin0"
0:00:00.032406796 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1270:gst_element_get_compatible_pad:<decodebin0> Could not find a compatible pad to link to videoconvert0:sink
0:00:00.032409901 734154 0x569a1759d390 INFO                 default gstutils.c:2208:gst_element_link_pads_filtered: Could not link pads: decodebin0:(null) - videoconvert0:(null)
0:00:00.032416629 734154 0x569a1759d390 INFO            GST_PIPELINE subprojects/gstreamer/gst/parse/grammar.y:1058:gst_parse_perform_link: linking some pad of GstVideoConvert named videoconvert0 to some pad of GstAutoVideoSink named video_sink (0/0) with caps "(NULL)"
0:00:00.032419668 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstutils.c:1818:gst_element_link_pads_full: trying to link element videoconvert0:(any) to element video_sink:(any)
0:00:00.032422415 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1080:gst_pad_check_link: trying to link videoconvert0:src and video_sink:sink
0:00:00.032424680 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert0:sink> pad has no peer
0:00:00.032699543 734154 0x569a1759d390 INFO                GST_PADS gstutils.c:1634:prepare_link_maybe_ghosting: videoconvert0 and video_sink in same bin, no need for ghost pads
0:00:00.032703548 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link videoconvert0:src and video_sink:sink
0:00:00.032705680 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<videoconvert0:sink> pad has no peer
0:00:00.032987786 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked videoconvert0:src and video_sink:sink, successful
0:00:00.032990249 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.032992239 734154 0x569a1759d390 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<videoconvert0:src> Received event on flushing pad. Discarding
0:00:00.032996400 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline2]: looking up child element video_source
0:00:00.033005989 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:4395:gst_bin_get_by_name: [pipeline2]: looking up child element video_sink
0:00:00.033421672 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink> current NULL pending VOID_PENDING, desired next READY
0:00:00.033427486 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<fake-video-sink> completed state change to NULL
0:00:00.033432158 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking sink:proxypad3(0x569a1796f550) and fake-video-sink:sink(0x569a179701f0)
0:00:00.033435179 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked sink:proxypad3 and fake-video-sink:sink
0:00:00.033437668 734154 0x569a1759d390 INFO           GST_PARENTAGE gstbin.c:1805:gst_bin_remove_func:<video_sink> removed child "fake-video-sink"
0:00:00.033442014 734154 0x569a1759d390 INFO         GST_REFCOUNTING gstelement.c:3400:gst_element_dispose:<fake-video-sink> 0x569a1796fef0 dispose
0:00:00.033444309 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:875:gst_element_remove_pad:<fake-video-sink> removing pad 'sink'
0:00:00.033447817 734154 0x569a1759d390 INFO         GST_REFCOUNTING gstelement.c:3446:gst_element_dispose:<fake-video-sink> 0x569a1796fef0 parent class dispose
0:00:00.033449947 734154 0x569a1759d390 INFO         GST_REFCOUNTING gstelement.c:3478:gst_element_finalize:<fake-video-sink> 0x569a1796fef0 finalize
0:00:00.033451914 734154 0x569a1759d390 INFO         GST_REFCOUNTING gstelement.c:3483:gst_element_finalize:<fake-video-sink> 0x569a1796fef0 finalize parent
0:00:00.033940794 734154 0x569a1759d390 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstxvimagesink.so" loaded
0:00:00.033979231 734154 0x569a1759d390 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "xvimagesink"
0:00:00.033984239 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseSink@0x569a1797bc30> adding pad 'sink'
0:00:00.033989068 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad video_sink-actual-sink-xvimage:sink
0:00:00.034656993 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_sink-actual-sink-xvimage> completed state change to READY
0:00:00.034663492 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_sink-actual-sink-xvimage> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.034865139 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_sink-actual-sink-xvimage> completed state change to NULL
0:00:00.034868708 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_sink-actual-sink-xvimage> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:00.034882193 734154 0x569a1759d390 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad video_sink-actual-sink-xvimage:sink
0:00:00.034885360 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link sink:proxypad3 and video_sink-actual-sink-xvimage:sink
0:00:00.034888148 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked sink:proxypad3 and video_sink-actual-sink-xvimage:sink, successful
0:00:00.034890121 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.034896172 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink-actual-sink-xvimage> current NULL pending VOID_PENDING, desired next READY
0:00:00.035231887 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_sink-actual-sink-xvimage> completed state change to READY
0:00:00.035235475 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_sink-actual-sink-xvimage> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035241213 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<video_sink> child 'video_sink-actual-sink-xvimage' changed state to 2(READY) successfully
0:00:00.035244503 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_sink> completed state change to READY
0:00:00.035246840 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_sink> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035249970 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'video_sink' changed state to 2(READY) successfully
0:00:00.035253011 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert0> current NULL pending VOID_PENDING, desired next READY
0:00:00.035255180 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert0> completed state change to READY
0:00:00.035257415 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035260127 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'videoconvert0' changed state to 2(READY) successfully
0:00:00.035263546 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<decodebin0> current NULL pending VOID_PENDING, desired next READY
0:00:00.035267642 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<typefind> current NULL pending VOID_PENDING, desired next READY
0:00:00.035270860 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<typefind> completed state change to READY
0:00:00.035273877 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<typefind> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035277280 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<decodebin0> child 'typefind' changed state to 2(READY) successfully
0:00:00.035279907 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<decodebin0> completed state change to READY
0:00:00.035282612 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<decodebin0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035285260 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'decodebin0' changed state to 2(READY) successfully
0:00:00.035288585 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse0> current NULL pending VOID_PENDING, desired next READY
0:00:00.035290750 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse0> completed state change to READY
0:00:00.035293332 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035295944 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'h264parse0' changed state to 2(READY) successfully
0:00:00.035299040 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<queue2> current NULL pending VOID_PENDING, desired next READY
0:00:00.035301706 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<queue2> completed state change to READY
0:00:00.035304246 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<queue2> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035307527 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'queue2' changed state to 2(READY) successfully
0:00:00.035310344 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_source> current NULL pending VOID_PENDING, desired next READY
0:00:00.035313413 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_source> completed state change to READY
0:00:00.035315993 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_source> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035319357 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'video_source' changed state to 2(READY) successfully
0:00:00.035322096 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<pipeline2> completed state change to READY
0:00:00.035326009 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<pipeline2> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.035330378 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2070:gst_bin_get_state_func:<pipeline2> getting state
0:00:00.035337653 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035340896 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink-actual-sink-xvimage> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035348488 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<video_sink> child 'video_sink-actual-sink-xvimage' is changing state asynchronously to PAUSED
0:00:00.035355328 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'video_sink' is changing state asynchronously to PAUSED
0:00:00.035359027 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert0> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035367701 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert0> completed state change to PAUSED
0:00:00.035370328 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.035373614 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'videoconvert0' changed state to 3(PAUSED) successfully
0:00:00.035376652 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<decodebin0> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035385881 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<typefind> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035392348 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<typefind> completed state change to PAUSED
0:00:00.035394959 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<typefind> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.035398186 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<decodebin0> child 'typefind' changed state to 3(PAUSED) successfully
0:00:00.035401575 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'decodebin0' is changing state asynchronously to PAUSED
0:00:00.035404642 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse0> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035430905 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse0> completed state change to PAUSED
0:00:00.035433916 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.035437470 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'h264parse0' changed state to 3(PAUSED) successfully
0:00:00.035440680 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<queue2> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035461669 734154 0x569a1759d390 INFO                    task gsttask.c:531:gst_task_set_lock: setting stream lock 0x569a179528a0 on task 0x569a1799daa0
0:00:00.035464996 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:6363:gst_pad_start_task:<queue2:src> created task 0x569a1799daa0
0:00:00.035550571 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<queue2> completed state change to PAUSED
0:00:00.035553786 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<queue2> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.035557280 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'queue2' changed state to 3(PAUSED) successfully
0:00:00.035560212 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_source> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.035568456 734154 0x569a1759d390 INFO                 basesrc gstbasesrc.c:1454:gst_base_src_do_seek:<video_source> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.035574025 734154 0x569a1759d390 INFO                    task gsttask.c:531:gst_task_set_lock: setting stream lock 0x569a179520f0 on task 0x569a1799e620
0:00:00.035576811 734154 0x569a1759d390 INFO                GST_PADS gstpad.c:6363:gst_pad_start_task:<video_source:src> created task 0x569a1799e620
0:00:00.035665428 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_source> completed state change to PAUSED
0:00:00.035668382 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_source> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.035672076 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2982:gst_bin_change_state_func:<pipeline2> child 'video_source' changed state to 3(PAUSED) successfully without preroll
0:00:00.035675419 734154 0x569a1759d390 INFO                pipeline gstpipeline.c:539:gst_pipeline_change_state:<pipeline2> pipeline is live
0:00:00.035678729 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2796:gst_element_continue_state:<pipeline2> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:00.035681676 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<pipeline2> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:00.035684800 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2804:gst_element_continue_state:<pipeline2> continue state change PAUSED to PLAYING, final PLAYING
0:00:00.035694878 734154 0x74255c000e30 INFO        GST_ELEMENT_PADS gstelement.c:1013:gst_element_get_static_pad: no such pad 'sink' in element "video_source"
0:00:00.035709029 734154 0x74255c000e30 FIXME                default gstutils.c:4088:gst_element_decorate_stream_id_internal:<video_source> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:00.035713706 734154 0x569a1759d390 INFO               GST_EVENT gstevent.c:1557:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:00.035724154 734154 0x569a1759d390 INFO                     bin gstbin.c:2767:gst_bin_do_latency_func:<pipeline2> configured latency of 0:00:00.000000000
0:00:00.035729737 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink> current READY pending PAUSED, desired next PLAYING
0:00:00.035732749 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'video_sink' is changing state asynchronously to PLAYING
0:00:00.035735610 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:00.035738280 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert0> completed state change to PLAYING
0:00:00.035741833 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.035745039 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'videoconvert0' changed state to 4(PLAYING) successfully
0:00:00.035747773 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<decodebin0> current READY pending PAUSED, desired next PLAYING
0:00:00.035750034 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'decodebin0' is changing state asynchronously to PLAYING
0:00:00.035752638 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:00.035754782 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse0> completed state change to PLAYING
0:00:00.035756801 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.035759395 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'h264parse0' changed state to 4(PLAYING) successfully
0:00:00.035761000 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<typefind:src> pad has no peer
0:00:00.035761987 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<queue2> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:00.035770860 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<queue2> completed state change to PLAYING
0:00:00.035773073 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<queue2> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.035775769 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'queue2' changed state to 4(PLAYING) successfully
0:00:00.035779222 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_source> completed state change to PLAYING
0:00:00.035781412 734154 0x569a1759d390 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_source> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.035784088 734154 0x569a1759d390 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'video_source' changed state to 4(PLAYING) successfully
0:00:00.035788978 734154 0x74255c000e30 INFO               GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au
0:00:00.035824644 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, parsed=(boolean)true
0:00:00.035841433 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, parsed=(boolean)true
0:00:00.035851804 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad typefind:src
0:00:00.035855961 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad typefind:sink
0:00:00.035878442 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link typefind:src and decodepad0:proxypad4
0:00:00.035884032 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked typefind:src and decodepad0:proxypad4, successful
0:00:00.035886953 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
using system MAC address 00:93:37:7a:31:cc
Initialized server socket(s)
0:00:00.036971283 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking typefind:src(0x569a17961b30) and decodepad0:proxypad4(0x742558002e30)
0:00:00.036980510 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked typefind:src and decodepad0:proxypad4
0:00:00.036986840 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link typefind:src and decodepad0:proxypad4
0:00:00.036994248 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked typefind:src and decodepad0:proxypad4, successful
0:00:00.036997118 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037009200 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking typefind:src(0x569a17961b30) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037015540 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked typefind:src and decodepad0:proxypad4
0:00:00.037021516 734154 0x74255c000b90 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "h264parse"
0:00:00.037034930 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x742558063850> adding pad 'sink'
0:00:00.037042403 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseParse@0x742558063850> adding pad 'src'
0:00:00.037054029 734154 0x74255c000b90 INFO               baseparse gstbaseparse.c:4067:gst_base_parse_set_pts_interpolation:<GstH264Parse@0x742558063850> PTS interpolation: no
0:00:00.037057877 734154 0x74255c000b90 INFO               baseparse gstbaseparse.c:4085:gst_base_parse_set_infer_ts:<GstH264Parse@0x742558063850> TS inferring: no
0:00:00.037070764 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link typefind:src and h264parse1:sink
0:00:00.037075373 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked typefind:src and h264parse1:sink, successful
0:00:00.037077954 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037086532 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to READY
0:00:00.037090724 734154 0x74255c000b90 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.037100022 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad h264parse1:src
0:00:00.037111311 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link h264parse1:src and decodepad0:proxypad4
0:00:00.037116155 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked h264parse1:src and decodepad0:proxypad4, successful
0:00:00.037119545 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037123191 734154 0x74255c000b90 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<h264parse1:src> Received event on flushing pad. Discarding
0:00:00.037183747 734154 0x74255c000b90 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "capsfilter"
0:00:00.037212007 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x742558069210> adding pad 'sink'
0:00:00.037219395 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstBaseTransform@0x742558069210> adding pad 'src'
0:00:00.037226619 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037236126 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2796:gst_element_continue_state:<capsfilter0> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:00.037240787 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<capsfilter0> notifying about state-changed NULL to READY (PAUSED pending)
0:00:00.037246150 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2804:gst_element_continue_state:<capsfilter0> continue state change READY to PAUSED, final PAUSED
0:00:00.037252926 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<capsfilter0> completed state change to PAUSED
0:00:00.037256947 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<capsfilter0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.037266968 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking h264parse1:src(0x742558064930) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037273306 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked h264parse1:src and decodepad0:proxypad4
0:00:00.037279134 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad capsfilter0:sink
0:00:00.037284220 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link h264parse1:src and capsfilter0:sink
0:00:00.037288549 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked h264parse1:src and capsfilter0:sink, successful
0:00:00.037291867 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037295385 734154 0x74255c000b90 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<h264parse1:src> Received event on flushing pad. Discarding
0:00:00.037300706 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad capsfilter0:src
0:00:00.037306712 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link capsfilter0:src and decodepad0:proxypad4
0:00:00.037311125 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked capsfilter0:src and decodepad0:proxypad4, successful
0:00:00.037314522 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037319164 734154 0x74255c000b90 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<h264parse1:src> Received event on flushing pad. Discarding
0:00:00.037355848 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse1> completed state change to PAUSED
0:00:00.037361122 734154 0x74255c000b90 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.037392060 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer
0:00:00.037434412 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, parsed=(boolean)true
0:00:00.037448118 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer
0:00:00.037457203 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer
0:00:00.037465325 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:918:gst_event_new_caps: creating caps event video/x-h264, profile=(string)main, width=(int)1, height=(int)1, alignment=(string)au, stream-format=(string)byte-stream, parsed=(boolean)true
0:00:00.037474896 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking capsfilter0:src(0x742558069860) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037481173 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked capsfilter0:src and decodepad0:proxypad4
0:00:00.037487100 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link capsfilter0:src and decodepad0:proxypad4
0:00:00.037491124 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked capsfilter0:src and decodepad0:proxypad4, successful
0:00:00.037493809 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037547254 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking capsfilter0:src(0x742558069860) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037553788 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked capsfilter0:src and decodepad0:proxypad4
0:00:00.037559382 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link capsfilter0:src and decodepad0:proxypad4
0:00:00.037563312 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked capsfilter0:src and decodepad0:proxypad4, successful
0:00:00.037565911 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037574856 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking capsfilter0:src(0x742558069860) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037580256 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked capsfilter0:src and decodepad0:proxypad4
0:00:00.037585684 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link capsfilter0:src and decodepad0:proxypad4
0:00:00.037589466 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked capsfilter0:src and decodepad0:proxypad4, successful
0:00:00.037591932 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.037602007 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2145:gst_pad_unlink: unlinking capsfilter0:src(0x742558069860) and decodepad0:proxypad4(0x742558002e30)
0:00:00.037607398 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstpad.c:2200:gst_pad_unlink: unlinked capsfilter0:src and decodepad0:proxypad4
0:00:00.039628456 734154 0x74255c000b90 INFO               vadisplay gstvadisplay_drm.c:155:gst_va_display_drm_create_va_display:<vadisplaydrm0> DRM render node with kernel driver i915
0:00:00.039678493 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm0> VA info: VA-API version 1.21.0
0:00:00.039693530 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm0> VA info: Trying to open /usr/lib/dri/iHD_drv_video.so
0:00:00.040489858 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm0> VA info: Found init function __vaDriverInit_1_21
0:00:00.042634364 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm0> VA info: va_openDriver() returns 0
0:00:00.042642587 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:405:gst_va_display_initialize:<vadisplaydrm0> VA-API version 1.21
0:00:00.042645724 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:176:_gst_va_display_filter_driver: VA-API driver vendor: Intel iHD driver for Intel(R) Gen Graphics - 24.2.0 ()
0:00:00.042650843 734154 0x74255c000b90 INFO                      va gstvadevice_linux.c:104:gst_va_device_find_devices: Found VA-API device: /dev/dri/renderD128
0:00:00.100855291 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_ARGB => { fourcc BGRA, drm fourcc BA24, LSB, bpp 32, depth 32, R 0x0000ff00, G 0x00ff0000, B 0xff000000, A 0x000000ff }
0:00:00.100868319 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_BGRA => { fourcc ARGB, drm fourcc AR24, LSB, bpp 32, depth 32, R 0x00ff0000, G 0x0000ff00, B 0x000000ff, A 0xff000000 }
0:00:00.100871907 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_ABGR => { fourcc RGBA, drm fourcc RA24, LSB, bpp 32, depth 32, R 0xff000000, G 0x00ff0000, B 0x0000ff00, A 0x000000ff }
0:00:00.100874960 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_RGBA => { fourcc ABGR, drm fourcc AB24, LSB, bpp 32, depth 32, R 0x000000ff, G 0x0000ff00, B 0x00ff0000, A 0xff000000 }
0:00:00.100878194 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_xRGB => { fourcc BGRX, drm fourcc BX24, LSB, bpp 32, depth 24, R 0x0000ff00, G 0x00ff0000, B 0xff000000, A 0000000000 }
0:00:00.100881485 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_BGRx => { fourcc XRGB, drm fourcc XR24, LSB, bpp 32, depth 24, R 0x00ff0000, G 0x0000ff00, B 0x000000ff, A 0000000000 }
0:00:00.100884540 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_xBGR => { fourcc RGBX, drm fourcc RX24, LSB, bpp 32, depth 24, R 0xff000000, G 0x00ff0000, B 0x0000ff00, A 0000000000 }
0:00:00.100887607 734154 0x74255c000b90 INFO               vadisplay gstvavideoformat.c:458:fix_map: GST_VIDEO_FORMAT_RGBx => { fourcc XBGR, drm fourcc XB24, LSB, bpp 32, depth 24, R 0x000000ff, G 0x0000ff00, B 0x00ff0000, A 0000000000 }
0:00:00.104049248 734154 0x74255c000b90 INFO      GST_PLUGIN_LOADING gstplugin.c:995:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstva.so" loaded
0:00:00.104056762 734154 0x74255c000b90 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:489:gst_element_factory_create_with_properties: creating element "vah264dec"
0:00:00.104124359 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstVideoDecoder@0x7425580a68a0> adding pad 'sink'
0:00:00.104129014 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:758:gst_element_add_pad:<GstVideoDecoder@0x7425580a68a0> adding pad 'src'
0:00:00.104151828 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link capsfilter0:src and vah264dec0:sink
0:00:00.104155442 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked capsfilter0:src and vah264dec0:sink, successful
0:00:00.104157934 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.104173055 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<vah264dec0:src> pad has no peer
0:00:00.104175579 734154 0x74255c000b90 INFO             GST_CONTEXT gstvautils.c:83:pad_query:<vah264dec0:src> pad peer query failed
0:00:00.104182369 734154 0x74255c000b90 INFO             GST_CONTEXT gstvautils.c:83:pad_query:<vah264dec0:sink> pad peer query failed
0:00:00.104184586 734154 0x74255c000b90 INFO             GST_CONTEXT gstvautils.c:152:gst_va_context_query:<vah264dec0> posting need context message
0:00:00.104229270 734154 0x74255c000b90 INFO               vadisplay gstvadisplay_drm.c:155:gst_va_display_drm_create_va_display:<vadisplaydrm1> DRM render node with kernel driver i915
0:00:00.104263721 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm1> VA info: VA-API version 1.21.0
0:00:00.104269443 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm1> VA info: Trying to open /usr/lib/dri/iHD_drv_video.so
0:00:00.104301836 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm1> VA info: Found init function __vaDriverInit_1_21
0:00:00.105481291 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:353:_va_info:<vadisplaydrm1> VA info: va_openDriver() returns 0
0:00:00.105487562 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:405:gst_va_display_initialize:<vadisplaydrm1> VA-API version 1.21
0:00:00.105490558 734154 0x74255c000b90 INFO               vadisplay gstvadisplay.c:176:_gst_va_display_filter_driver: VA-API driver vendor: Intel iHD driver for Intel(R) Gen Graphics - 24.2.0 ()
0:00:00.105499392 734154 0x74255c000b90 INFO             GST_CONTEXT gstvautils.c:197:gst_va_element_propagate_display_context:<vah264dec0> post have context (0x7425581cecd0) message with display (0x74255808d270)
0:00:00.105553345 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<vah264dec0> completed state change to READY
0:00:00.105557097 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<vah264dec0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.105574764 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<vah264dec0:src> pad has no peer
0:00:00.105592377 734154 0x74255c000b90 INFO        GST_ELEMENT_PADS gstelement.c:1016:gst_element_get_static_pad: found pad vah264dec0:src
0:00:00.105600170 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2440:gst_pad_link_prepare: trying to link vah264dec0:src and decodepad0:proxypad4
0:00:00.105603232 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:2621:gst_pad_link_full: linked vah264dec0:src and decodepad0:proxypad4, successful
0:00:00.105605166 734154 0x74255c000b90 INFO               GST_EVENT gstevent.c:1687:gst_event_new_reconfigure: creating reconfigure event
0:00:00.105607839 734154 0x74255c000b90 INFO               GST_EVENT gstpad.c:6017:gst_pad_send_event_unchecked:<vah264dec0:src> Received event on flushing pad. Discarding
0:00:00.105624533 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<vah264dec0> completed state change to PAUSED
0:00:00.105627208 734154 0x74255c000b90 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<vah264dec0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.105643525 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer
0:00:00.105678516 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer
0:00:00.105697238 734154 0x74255c000b90 INFO                typefind gsttypefindelement.c:183:gst_type_find_element_have_type:<typefind> found caps video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, parsed=(boolean)true, probability=100
0:00:00.105715306 734154 0x74255c000b90 INFO                GST_PADS gstpad.c:4398:gst_pad_peer_query:<'':decodepad0> pad has no peer

connecting:

Accepted IPv6 client on socket 452
Local: fe80:0000:0000:0000:1ea6:c4fa:4ac8:9af3
Remote: fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
connection request from Meins (iPhone13,1) with deviceID = FC:66:CF:DF:2E:52

Client identified as User-Agent: AirPlay/760.20.1
client is using IPV6 (untested!)
Accepted IPv6 client on socket 454
Local: fe80:0000:0000:0000:1ea6:c4fa:4ac8:9af3
Remote: fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
raop_rtp_mirror starting mirroring
0:00:44.257166131 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink> current READY pending PAUSED, desired next PAUSED
0:00:44.257181112 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'video_sink' is changing state asynchronously to PAUSED
0:00:44.257184115 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert0> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:44.257186764 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert0> completed state change to PAUSED
0:00:44.257188966 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:44.257204836 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'videoconvert0' changed state to 3(PAUSED) successfully
0:00:44.257207885 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<decodebin0> current READY pending PAUSED, desired next PAUSED
0:00:44.257210116 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'decodebin0' is changing state asynchronously to PAUSED
0:00:44.257212791 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse0> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:44.257215683 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse0> completed state change to PAUSED
0:00:44.257217642 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:44.257220340 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'h264parse0' changed state to 3(PAUSED) successfully
0:00:44.257222609 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<queue2> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:44.257224810 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<queue2> completed state change to PAUSED
0:00:44.257226823 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<queue2> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:44.257229172 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'queue2' changed state to 3(PAUSED) successfully
0:00:44.257231381 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_source> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:44.257236196 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_source> completed state change to PAUSED
0:00:44.257238082 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_source> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:44.257241894 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2982:gst_bin_change_state_func:<pipeline2> child 'video_source' changed state to 3(PAUSED) successfully without preroll
0:00:44.257245087 734154 0x742540000f40 INFO                pipeline gstpipeline.c:539:gst_pipeline_change_state:<pipeline2> pipeline is live
0:00:44.257247132 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<pipeline2> completed state change to PAUSED
0:00:44.257249746 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<pipeline2> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending)
0:00:44.257267221 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2070:gst_bin_get_state_func:<pipeline2> getting state
0:00:44.257306754 734154 0x742540000f40 INFO               GST_EVENT gstevent.c:1557:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:44.257313674 734154 0x742540000f40 INFO                     bin gstbin.c:2767:gst_bin_do_latency_func:<pipeline2> configured latency of 0:00:00.000000000
0:00:44.257318970 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<video_sink> current READY pending PAUSED, desired next PLAYING
0:00:44.257323777 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'video_sink' is changing state asynchronously to PLAYING
0:00:44.257328639 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<videoconvert0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:44.257331451 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<videoconvert0> completed state change to PLAYING
0:00:44.257333429 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:44.257336723 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'videoconvert0' changed state to 4(PLAYING) successfully
0:00:44.257339712 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<decodebin0> current READY pending PAUSED, desired next PLAYING
0:00:44.257342247 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2946:gst_bin_change_state_func:<pipeline2> child 'decodebin0' is changing state asynchronously to PLAYING
0:00:44.257344723 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<h264parse0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:44.257347171 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<h264parse0> completed state change to PLAYING
0:00:44.257349876 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:44.257354123 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'h264parse0' changed state to 4(PLAYING) successfully
0:00:44.257357481 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2480:gst_bin_element_set_state:<queue2> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:44.257360213 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<queue2> completed state change to PLAYING
0:00:44.257362658 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<queue2> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:44.257369707 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'queue2' changed state to 4(PLAYING) successfully
0:00:44.257373127 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2824:gst_element_continue_state:<video_source> completed state change to PLAYING
0:00:44.257375102 734154 0x742540000f40 INFO              GST_STATES gstelement.c:2724:_priv_gst_element_state_changed:<video_source> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:44.257390126 734154 0x742540000f40 INFO              GST_STATES gstbin.c:2939:gst_bin_change_state_func:<pipeline2> child 'video_source' changed state to 4(PLAYING) successfully
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time

sorry for dump of long output

fduncanh commented 5 months ago

Good,
do

export GST_DEBUG=0
uxplay -d

I just want to see if you get a message

X11 UxPlay Window not found in 255 search attempts

feuera commented 5 months ago

the self compiled version does not output that Window error (not even with 5) o1.txt

fduncanh commented 5 months ago

OK it seems to be the "invalid ntp time" error, see #279

seems something on arch, maybe connected to gstreamer-1.24. I was going to look into this, but havent done so yet. See if #279 gives a fix.

video renderer resumed
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
377039.565578 ntp_time         <<<<<<<<<<<<<<<<<<<<<<<,this is corrupted, invalid
1713544911.980577 base_time
raop_rtp video: now = 1713544923.044345, ntp = 377039.615755, latency = 1713167883.428590, ts = 377039.615755, 00 00 00 00 
video renderer resumed
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
377039.615755 ntp_time

fduncanh commented 5 months ago

@feuera also try clearing the gstreamer cache

https://github.com/FDH2/UxPlay#4-gstreamer-issues-missing-plugins-etc

fduncanh commented 5 months ago

@feuera are you using AUR or github?

fduncanh commented 5 months ago

@feuera

I am seeing your issues on Arch, if I start streaming (works) , stop streaming , and restart streaming (broken).

This might be from some change in gstreamer-1.24. Will get back to you when more info is found.

feuera commented 5 months ago

Thanks for looking into it. I used aur, rebuilding did not solve the issue. For changing that number I used github. I also tried clearing cache. Anyways. I downgraded all my gstreamer stuff to 1.22.10-1. It works.

fduncanh commented 5 months ago

I build gstreamer-1.24 for myself on both Arch and a different linux distribution (my usual one)

sometimes it works , sometimes I get your problem on the other distro as well. So its not Arch specific, but some new change in gstreamer-1.24...... going to be a pain to find it....

Good you could downgrade.

fduncanh commented 5 months ago

@feuera

Is it easy to downgrade to gstreamer-1.22.10 on Arch?

maybe you could post instructions here?

feuera commented 5 months ago

used downgrade tool from aur

https://github.com/archlinux-downgrade/downgrade

https://wiki.archlinux.org/title/downgrading_packages

sudo downgrade gstreamer then selecting version of liking (chose 1.22.10) you will get error with dependency for other gstreamer libs/packages (for me gst-plugins-base-libs at first) add dependency lib to downgrade cmd. repeat until all dependencies are included (don't know if there is a recursive switch in downgrade) ended up with full cmd line:

sudo downgrade gstreamer gst-plugins-base-libs gst-libav gst-plugins-bad-libs gst-plugins-base gst-plugins-good gst-plugins-ugly gst-plugin-gtk gst-plugin-va gst-plugins-bad

in the end it asks whether you want to add the package to ignorepkg (prevent future updates)

fduncanh commented 5 months ago

The issue is now identified. gstreamer 1.24 revised the pause/resume behavior of gstreamer, with commit e506f9c2

(immediately followed by related commits 47d79eed and 7e3f8e79)

Uxplay added some code using resume/commit in v1.66 https://github.com/FDH2/UxPlay/commit/660a2dc378ec22bbdabfc2bd9558755d8e3b4c37

this UxPlay code will need to be revised. Luckily ubuntu24.04LTS stays with gstreamer-1.22.10. Only Arch is already on 1.24, and it can be downgraded.

fduncanh commented 5 months ago

@feuera

We released UxPlay-1.68.3 with a test for GStreamer>=1.24.x that just skips the problematic code if UxPlay is compiled to use 1.24.x or later. Should soon be in AUR hopefully, and is on github. The skipped code was fixing something, but I couldn't get UxPlay to exhibit the problem #209 it was supposed to fix, so maybe it's not needed anymore.

If you keep using GStreamer1.22.x, that code will not be skipped.

Thanks for bringing this to our attention.

feuera commented 5 months ago

@fduncanh just upgraded gstreamer (+libs) 1.24.x and tried from aur uxplay (1:1.68.3-1) and uxplay-git
did not work

raop_rtp_mirror starting mirroring
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
431898.150633 ntp_time
1713861403.850689 base_time
...

then I downgraded to 1.22 and reinstalled uxplay (clean build from aur) does not seem to work any more; same base_time error from above maybe I did something wrong, will try again soon

Just checked building from github (gstreamer 1.22) tags/v1.68.2 works tags/v1.68.3 gives error from above

fduncanh commented 5 months ago

Thats a different error, you had two errors, the first one (due to gstreamer-1.24) is fixed (with a temporary quick fix).

The version obtained from github (not from AUR) was working when I tested.

I havent tested the AUR version yet.

what kind of computer are you running on? (can you post a uxplay -d output showiing the invalid ntptime error)

feuera commented 5 months ago

Core-i7 endeavour os (=arch) i3 wm (x11) 1.24 gstreamer uxplay -d

raop_rtp video: now = 1713887653.703808, ntp = 434247.704748, latency = 1713453405.999060, ts = 434247.704748, 00 10 00 00 
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
434247.704748 ntp_time
1713887647.487847 base_time

fduncanh commented 5 months ago

I just tested the AUR version , worked fine for me.

434247.704748 ntp_time 1713887647.487847 base_time

The ntp_time should have been converted to unix time (like base_time) There must be something fragile in the conversion. It will be tricky to find if I cannot reproduce the error.

please post a more complete log so I can see the full sequence of what happened for you

fduncanh commented 5 months ago

with your help, I can probably fix this easily.

You will need to modify uxplay.cpp in the code you downloaded from AUR, and rebuild.

the code involved in uxplay.cpp is (original code)

extern "C" void video_process (void *cls, raop_ntp_t *ntp, h264_decode_struct *data) {
    if (dump_video) {
        dump_video_to_file(data->data, data->data_len);
    }
    if (use_video) {
        if (!remote_clock_offset) {
            remote_clock_offset = data->ntp_time_local - data->ntp_time_remote;
        }
        data->ntp_time_remote = data->ntp_time_remote + remote_clock_offset;
        video_renderer_render_buffer(data->data, &(data->data_len), &(data->nal_count), &(data->ntp_time_remote));
    }
}

I am guessing that remote_clock_offset was not set.

check this with modified code with printf added


extern "C" void video_process (void *cls, raop_ntp_t *ntp, h264_decode_struct *data) {
    if (dump_video) {
        dump_video_to_file(data->data, data->data_len);
    }
    if (use_video) {
        if (!remote_clock_offset) {
            printf("local time %llu remote %llu\n", data->ntp_time_local, data->ntp_time_remote);
            remote_clock_offset = data->ntp_time_local - data->ntp_time_remote;
        printf("video: setting remote_clock_offset: %llu\n", remote_clock_offset); 
        }
    printf("%llu   %llu  ", data->ntp_time_remote, remote_clock_offset);
        data->ntp_time_remote = data->ntp_time_remote + remote_clock_offset;
    printf("%llu\n", data->ntp_time_remote);
        video_renderer_render_buffer(data->data, &(data->data_len), &(data->nal_count), &(data->ntp_time_remote));
    }
}

fduncanh commented 5 months ago

I modified the code above

EDIT: its at uxplay.cpp line 1473

feuera commented 5 months ago

using version from git tags/v1.68.3

local time 434815011480041 remote 434815011480041
video: setting remote_clock_offset: 0
434815011480041   0  434815011480041
*** ERROR: *** invalid ntp_time < gst_video_pipeline_base_time
434815.011480 ntp_time
1713891474.733078 base_time

by the way, using -vsync no seems to overcome/avoid the issue

fduncanh commented 5 months ago

Thats strange! local and remote time should not be the same!

local time should be unix time 171389147433078 .......... (micro seconds since jan 1 1970)

fduncanh commented 5 months ago

yes, vsync no will avoid the issue: it does not use timestamps

fduncanh commented 5 months ago

But I need to trackdown why local time is replaced by remotetime when you run uxplay.

fduncanh commented 5 months ago

can you run uxplay -d and post the whole output

feuera commented 5 months ago

full output of very short session: out.txt

fduncanh commented 5 months ago

This call to raop_ntp.c failed to convert the clients ntp time to server unix time presumably because raop_ntp->sync_offset was 0

 * Returns the remote wall clock time in nano seconds for the given point in local clock time
 */
uint64_t raop_ntp_convert_local_time(raop_ntp_t *raop_ntp, uint64_t local_time) {
    MUTEX_LOCK(raop_ntp->sync_params_mutex);
    int64_t offset = raop_ntp->sync_offset;
    MUTEX_UNLOCK(raop_ntp->sync_params_mutex);
    return (uint64_t) ((int64_t) local_time + offset);
}

fduncanh commented 5 months ago

Your out.txt shows the ntp initialization:

Client identified as User-Agent: AirPlay/760.20.1
timing_rport = 58378
raop_ntp parse remote ip = fe80:0000:0000:0000:14da:1a69:750a:e943
raop_ntp starting time
raop_ntp local timing port socket 453 port UDP 36498

raop_ntp send time type_t=82 packetlen = 32, now = 1713892728.370680
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 d2 6b f8 5e e4 e7 1b 

raop_rtp parse remote ip = fe80:0000:0000:0000:14da:1a69:750a:e943
raop_rtp_mirror parse remote ip = fe80:0000:0000:0000:14da:1a69:750a:e943
eport = 45125, tport = 36498
RTSP/1.0 200 OK 
CSeq: 3 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 77 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>timingPort</key>
        <integer>36498</integer>
        <key>eventPort</key>
        <integer>45125</integer>
</dict>
</plist>

Accepted IPv6 client on socket 454

but one should see the reply, as seen below from my system

Client identified as User-Agent: AirPlay/760.20.1
timing_rport = 61595
raop_ntp parse remote ip = 2600:4040:a039:4900:5930:e3ea:c195:9029
raop_ntp starting time
raop_ntp local timing port socket 26 port UDP 7011

raop_ntp send time type_t=82 packetlen = 32, now = 1713893542.154021
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 d2 6f 26 27 6d df 67 

raop_rtp parse remote ip = 2600:4040:a039:4900:5930:e3ea:c195:9029
raop_rtp_mirror parse remote ip = 2600:4040:a039:4900:5930:e3ea:c195:9029
eport = 7000, tport = 7011

RTSP/1.0 200 OK 
CSeq: 3 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 77 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>timingPort</key>
        <integer>7011</integer>
        <key>eventPort</key>
        <integer>7000</integer>
</dict>
</plist>

raop_ntp receive time type_t=83 packetlen = 32, now = 1713893542.156613 t1 = 129095.602404, t2 = 129095.602469
80 d3 00 07 00 00 00 00 e9 d2 6f 26 27 6d df 67 
83 ac 76 c7 9a 37 20 6f 83 ac 76 c7 9a 3b 6f 89 

raop_ntp sync correction = -1713764446552880160
Accepted IPv6 client on socket 27

fduncanh commented 5 months ago

your iphone client is using NTP, so I'm not sure why it did not send a reply to the ntp request

I think it's supposed to reply within 0.3 sec, or uxplay -d should show a message. (maybe should check that the NTP server has synchronized with the client before starting synchronized video)
need to find out if the client is just a bit slow (timing issue) or not sending the time signal.
can you post a "uxplay -vsync no -d " output? that way I can see if the ntp server eventually gets setup properly, even though " -vsync no" doesn't use it.

SETUP rtsp://fe80::1ea6:c4fa:4ac8:9af3/12493478968691279571 RTSP/1.0
Content-Length: 624
Content-Type: application/x-apple-binary-plist
CSeq: 3
DACP-ID: DFAEA4FB8D938EF2
Active-Remote: 4183858626
User-Agent: AirPlay/760.20.1

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>et</key>
        <integer>32</integer>
        <key>statsCollectionEnabled</key>
        <false/>
        <key>eiv</key>
        <data>
        dazfhN1eZgYqB/NCC8OY2A==
        </data>
        <key>sessionUUID</key>
        <string>AD61C0ED-C1A8-46D3-BFD2-BA3B2C8F5C6B</string>
        <key>timingProtocol</key>
        <string>NTP</string>             <----------------------------------NTP
        <key>osName</key>
        <string>iPhone OS</string>
        <key>osBuildVersion</key>
        <string>21E236</string>
        <key>sourceVersion</key>
        <string>760.20.1</string>
        <key>timingPort</key>
        <integer>58378</integer>
        <key>isScreenMirroringSession</key>
        <true/>
        <key>osVersion</key>
        <string>17.4.1</string>
 snip

feuera commented 5 months ago

there u go out_vsyncno.txt

fduncanh commented 5 months ago

Your iphone client is not sending ntp signals. This will break synchronised video, but not uxplay -vsync no.

(you may need "uxplay -vsync no -reset 0" to prevent uxplay termination after 5 ntp timeouts (15 sec)).

I added a test for this condition in latest github code.

Can you run latest github with "uxplay -vsync no" (without -d) for at least 30 seconds and post the output. (it may terminate after about 15 secs if ntp is not setup, let's see.)

It doesn't look like you have a firewall(?). In the run below uxplay sends and receives timing request from server port UDP 44013 to client port 57885, but nothing comes back

Client identified as User-Agent: AirPlay/760.20.1
timing_rport = 57885
raop_ntp parse remote ip = fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
raop_ntp starting time
raop_ntp local timing port socket 453 port UDP 44013

raop_ntp send time type_t=82 packetlen = 32, now = 1713896896.778051
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 d2 7c 40 c7 2e 57 d7 

raop_rtp parse remote ip = fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
raop_rtp_mirror parse remote ip = fe80:0000:0000:0000:0042:bc7e:e9cb:4ea3
eport = 42033, tport = 44013

raop_ntp receive timeout 1 (limit 5) (request sent 2024-04-23 20:28:16.778050890)

raop_ntp send time type_t=82 packetlen = 32, now = 1713896900.104713
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 d2 7c 44 1a ce 78 c9

*** ERROR: raop_ntp receive timeout 2 (limit 5) (request sent 2024-04-23 20:28:20.104713010)

fduncanh commented 5 months ago

However, you previously indicated gstreamer-1.22.10 was working (without this ntp problem, which has nothing to do with gstreamer ????)) was that with the same iphone client?

EDIT: a debug trace you posted earlier (4 days ago) shows ntp working fine (that time you had the gstreamer-1,24 issue only)

Client identified as User-Agent: AirPlay/760.20.1
timing_rport = 49960
raop_ntp parse remote ip = 192.168.0.6
raop_ntp starting time
raop_ntp local timing port socket 452 port UDP 44392

raop_ntp send time type_t=82 packetlen = 32, now = 1713524234.829391
80 d2 00 07 00 00 00 00 00 00 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 e9 cc cc 8a d4 52 fc 33 

raop_rtp parse remote ip = 192.168.0.6
raop_rtp_mirror parse remote ip = 192.168.0.6
eport = 42735, tport = 44392

RTSP/1.0 200 OK 
CSeq: 3 
Server: AirTunes/220.68 
Content-Type: application/x-apple-binary-plist 
Content-Length: 77 

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>timingPort</key>
    <integer>44392</integer>
    <key>eventPort</key>
    <integer>42735</integer>
</dict>
</plist>

raop_ntp receive time type_t=83 packetlen = 32, now = 1713524234.840508 t1 = 368509.622027, t2 = 368509.622108
80 d3 00 07 00 00 00 00 e9 cc cc 8a d4 52 fc 33 
83 b0 1d fd 9f 3d 30 53 83 b0 1d fd 9f 42 7b c9 

raop_ntp sync correction = -1713155725212881886

feuera commented 5 months ago

yes, runs into timeout after a while.

using tags/v1.68.2 ang gstreamer 1.22 everything works

fduncanh commented 5 months ago

closing, will open a new issue for parts of this

FDH2 / UxPlay

GStreamer 1.24 problems AND client ntp problems (was:X11 UxPlay Window not found in 5 search attempts) #284

define MAX_X11_SEARCH_ATTEMPTS 5 /should be less than 256 /

define MAX_X11_SEARCH_ATTEMPTS 5 /should be less than 256 /