Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] Windows下无法正常启动(Unable to start on Windows) #14

Closed
chengyuhui opened this issue Aug 21, 2021 · 18 comments
Closed

[BUG] Windows下无法正常启动(Unable to start on Windows) #14

chengyuhui opened this issue Aug 21, 2021 · 18 comments
Labels
bug Something isn't working

Comments

@chengyuhui
Copy link

Versions

  • System: Windows
  • System version: 21H1 (19043)
  • Processor architecture: x86_74
  • APP version: v0.5

Bug recurrence

Just start it.

Additional information

I have Python 3.9.2 (accessible via python) on this machine, maybe it is related?

Log

PasteBoard

Macast Loading Language: zh_CN
MPV started
ERROR:SSDPServer:not enough values to unpack (expected 2, got 1)
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:mpv ipc socket start connect
INFO:Render:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
INFO:Render:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
ERROR:Render:mpv ipc stopped
ERROR:Render:MPV stopped
@chengyuhui chengyuhui added the bug Something isn't working label Aug 21, 2021
@SurpassHR
Copy link

Same question on windows 11 21H2

  • Edition Windows 11 Pro Education
  • Version 21H2
  • OS build 22000.160
  • Experience Windows Feature Experience Pack 1000.22000.160.0
  • App version v0.5

Log

D:\Desktop>Macast-v0.5-debug.exe
Macast Loading Default Language en_US
ERROR:Render:MPV started
DEBUG:Macast:mpv_start
ERROR:SSDPServer:not enough values to unpack (expected 2, got 1)
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:mpv ipc socket start connect
INFO:Render:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
INFO:Render:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
DEBUG:Macast:tag_name: v0.5
ERROR:Render:mpv ipc stopped
ERROR:Render:MPV stopped
D:\Desktop>python --version
Python 3.9.6

By the way I think it has nothing to do with python version
Haven't tried to build from source

@xfangfang
Copy link
Owner

It seems that this is similar to win11 启动后无法投屏
But I can't reproduce this problem on my computers win10 20h2 and win11 dev build 21996.1

Yes, this problem is not related to the local python version

The log indicates that Macast exited for some reasons when it was just starting even before the initialization was completed. Because I removed some logs that I thought will not have errors, it is regrettable that it is difficult to obtain more meaningful information from the log.

I will improve the log output of the program tomorrow. hope this can help solve the bug.

@chengyuhui
Copy link
Author

Remove all Python instances from PATH yields this (I was surprised that I have 6 Python on my PC):

Macast Loading Language: zh_CN
get update info error: check_hostname requires server_hostname
ERROR:Render:MPV started
DEBUG:Macast:mpv_start
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:stoping mpv
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:mpv ipc socket start connect
INFO:Render:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
INFO:Render:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
ERROR:Render:mpv ipc stopped
ERROR:Render:MPV stopped
ERROR:SSDPServer:not enough values to unpack (expected 2, got 1)

The order of error messages is different (but consistently different)

@xfangfang
Copy link
Owner

Someone remind me that the application crash are caused by the failure of MPV to run on win11. I use MPV 0.33.0 in Macast. Can you test whether this version of MPV can run on your computer?
Or can you find an available MPV version?

@chengyuhui
Copy link
Author

The package you provided works normally on my machine, at least when launched normally. However, I don't know the status of IPC, which might be the problem.

@chengyuhui
Copy link
Author

chengyuhui commented Aug 24, 2021

The SSDPServer error seems to be coming from this:

Macast/macast/ssdp.py

Lines 97 to 100 in 17f003c

try:
header, payload = data.decode().split('\r\n\r\n')[:2]
except ValueError as err:
logger.error(err)

which should be safe to ignore (malformed packets from the network)?

Now I wonder why MPV is being commanded to stop even before it is started (the message mpv ipc socket start connect never showed up, which explains why we were getting a NoneType).

For reference, a correct startup should look like this (captured on another 21H1 system):

Macast Loading Default Language en_US
MPV started
ERROR:Render:mpv ipc socket start connect
INFO:Render:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
INFO:Render:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
DEBUG:Macast:tag_name: v0.5

@xfangfang
Copy link
Owner

ERROR:SSDPServer:not enough values to unpack (expected 2, got 1)

This line is caused by the closing of the SSDP thread, because the SSDP thread will be blocked while waiting to receive data, which will cause a random delay when closing this thread. Therefore, before closing the thread, I sent an empty packet to wake up the blocked thread.

Check the 1068 port of your system, Macast uses port 1068 for HTTP service. Check whether other devices can access http://[your computer's IP]:1068, such as http://192.168.1.101:1068

In my PC:

C:\Users\25530>netstat -ano | findstr 1068
  TCP    0.0.0.0:1068           0.0.0.0:0          LISTENING           2140

C:\Users\25530>netstat -ano | findstr 1900
  UDP    0.0.0.0:1900           *:*                                    2140
  UDP    [::1]:1900             *:*                                    6212
  UDP    [fe80::9c2e:af8d:2cb5:11ad%6]:1900  *:*                                    6212

C:\Users\25530>tasklist | findstr 2140
Macast-v0.5.exe                      2140 Console                    1    59,600 K

C:\Users\25530>tasklist | findstr 6212
svchost.exe                   6212 Services                   0      7,216 K

@xfangfang
Copy link
Owner

You can try this build: https://github.com/xfangfang/Macast/actions/runs/1162138219

This version add more logs, which may help solve the problem

@chengyuhui
Copy link
Author

.\Macast-v0.5-debug.exe : Macast Loading Language: zh_CN
MPV started
ERROR:SSDPServer:SSDP cannot set SO_REUSEPORT
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Started monitor thread 'Monitor'.
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Started monitor thread 'Autoreloader'.
ERROR:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "cherrypy\process\servers.py", line 225, in _start_http_thread
  File "cheroot\server.py", line 1836, in start
  File "cheroot\server.py", line 1791, in prepare
OSError: No socket could be created -- (('0.0.0.0', 1068): [WinError 10048] 通常每个套接字地址(协议/网络地址/端口)只允许使用一次。)

INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Bus STOPPING
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('0.0.0.0', 1068)) already shut down
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Removed handler for console events.
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Stopped thread 'Monitor'.
INFO:PLUGIN:Stoping RenderPlugin
ERROR:Render:stoping mpv
DEBUG:Render:send command: ['quit']
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Error in 'start' listener <bound method Server.start of <cherrypy._cpserver.Server object at 0x0000025B7
AE5C788>>
Traceback (most recent call last):
  File "cherrypy\process\wspbus.py", line 230, in publish
  File "cherrypy\_cpserver.py", line 180, in start
  File "cherrypy\process\servers.py", line 184, in start
  File "cherrypy\process\servers.py", line 246, in wait
  File "cherrypy\process\servers.py", line 225, in _start_http_thread
  File "cheroot\server.py", line 1836, in start
  File "cheroot\server.py", line 1791, in prepare
OSError: No socket could be created -- (('0.0.0.0', 1068): [WinError 10048] 通常每个套接字地址(协议/网络地址/端口)只允许使用一次。)

ERROR:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "cherrypy\process\wspbus.py", line 268, in start
  File "cherrypy\process\wspbus.py", line 248, in publish
cherrypy.process.wspbus.ChannelFailures: OSError("No socket could be created -- (('0.0.0.0', 1068): [WinError 10048] 通常每个套接字地址(协议/网络地址/端口)只允许使用一次。)")

INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Bus STOPPING
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('0.0.0.0', 1068)) already shut down
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE Handler for console events already off.
INFO:cherrypy.error:[24/Aug/2021:19:15:39] ENGINE No thread running for None.
INFO:PLUGIN:Stoping RenderPlugin
ERROR:Render:stoping mpv
DEBUG:Render:send command: ['quit']
ERROR:Render:sendCommand: 'NoneType' object has no attribute 'send_bytes'
ERROR:Render:cannot send command quit to mpv
ERROR:Render:mpv ipc socket start connect
DEBUG:Render:send command: ['observe_property', 1, 'volume']
DEBUG:Render:send command: ['observe_property', 2, 'time-pos']
DEBUG:Render:send command: ['observe_property', 3, 'pause']
DEBUG:Render:send command: ['observe_property', 4, 'mute']
DEBUG:Render:send command: ['observe_property', 5, 'duration']
DEBUG:Render:send command: ['observe_property', 6, 'track-list']
DEBUG:Render:{'request_id': 0, 'error': 'success'}
DEBUG:Render:{'request_id': 0, 'error': 'success'}
DEBUG:Render:{'request_id': 0, 'error': 'success'}
INFO:Render:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
DEBUG:Render:setState: Volume 100
INFO:Render:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
DEBUG:Render:{'request_id': 0, 'error': 'success'}
DEBUG:Render:setState: Mute False
DEBUG:Render:{'request_id': 0, 'error': 'success'}
DEBUG:Render:setState: CurrentTrackDuration 00:00:00
DEBUG:Render:setState: CurrentMediaDuration 00:00:00
DEBUG:Render:{'request_id': 0, 'error': 'success'}
DEBUG:Macast:tag_name: v0.5
DEBUG:Render:send command: ['quit']
Exiting... (Quit)
DEBUG:Render:{'data': None, 'request_id': 0, 'error': 'success'}
DEBUG:Render:
ERROR:Render:mpv ipc stopped
ERROR:Render:MPV stopped
INFO:PLUGIN:Stoping SSDPPlugin
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::upnp:rootdevice
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:device:MediaRenderer:1
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:RenderingControl:1
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:ConnectionManager:1
INFO:SSDPServer:Sending byebye notification for uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:AVTransport:1
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::upnp:rootdevice
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:device:MediaRenderer:1
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:RenderingControl:1
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:ConnectionManager:1
INFO:SSDPServer:Un-registering uuid:c4c0486c-62ac-4110-8a08-cf30d910ad42::urn:schemas-upnp-org:service:AVTransport:1
INFO:cherrypy.error:[24/Aug/2021:19:15:40] ENGINE Stopped thread 'Autoreloader'.
INFO:cherrypy.error:[24/Aug/2021:19:15:40] ENGINE Bus STOPPED
INFO:cherrypy.error:[24/Aug/2021:19:15:40] ENGINE Bus EXITING
INFO:cherrypy.error:[24/Aug/2021:19:15:40] ENGINE Bus EXITED

It seems that listening has failed, but I can do python -m http.server 1068 and access that server just fine, and there is nothing listening on 1068 before and after Macast is started according to resmon.

@xfangfang
Copy link
Owner

I still feel that some services on your system already used port 1068.

try this ?

netstat -ano | findstr 1068

@chengyuhui
Copy link
Author

That command outputs nothing.

@xfangfang
Copy link
Owner

I wonder if this can solve your problem: https://bbs.csdn.net/topics/391900623

@chengyuhui
Copy link
Author

chengyuhui commented Aug 25, 2021

I ran into this last weekend when writing my own SSDP/DLNA implementation in Rust for a smart speaker, and I'm pretty sure that I have fixed this problem (Python gives 10013 instead of 10048 in this case). It's not this.

@xfangfang xfangfang added this to To do in Current Work Aug 25, 2021
@xfangfang xfangfang moved this from To do to In progress in Current Work Aug 25, 2021
@xfangfang
Copy link
Owner

This build adds HTTP port checking. If there is a port conflict, it will automatically switch to an available port.
https://github.com/xfangfang/Macast/actions/runs/1192223767

@xfangfang
Copy link
Owner

Do you have time to test the new release? I feel this problem has been fixed.

@chengyuhui
Copy link
Author

It no longer crashes, but can not be searched by Bilibili (both live and video)

Macast Loading Language: zh_CN
Load renderer MPVRenderer done
using renderer: Default
INFO:cherrypy.error:[14/Sep/2021:19:58:43] ENGINE Started monitor thread 'Autoreloader'.
ERROR:SSDPServer:add membership 192.168.31.126
ERROR:SSDPServer:add membership 172.22.228.5
INFO:cherrypy.error:[14/Sep/2021:19:58:43] ENGINE Started monitor thread 'SSDP_NOTIFY_THREAD'.
INFO:cherrypy.error:[14/Sep/2021:19:58:43] ENGINE Bus STARTED
INFO:main:Server current run on port: 1068
ERROR:MPVRenderer:mpv ipc socket start connect
INFO:MPVRenderer:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 100.0}
INFO:MPVRenderer:{'event': 'property-change', 'id': 3, 'name': 'pause', 'data': False}
INFO:MPVRenderer:{'event': 'property-change', 'id': 1, 'name': 'volume', 'data': 50.0}
INFO:main:tag_name: v0.61
ERROR:main:get update info error: <lambda>() missing 1 required positional argument: '_'

@xfangfang
Copy link
Owner

There may be many reasons why Macast cannot be searched.
check: https://github.com/xfangfang/Macast/wiki/FAQ#unable-to-find-macast-from-your-dlna-client

After the recent update(v0.6.1), there is almost no bug feedback about this.

@xfangfang
Copy link
Owner

Because the original problem has been solved, closing this issue now.
If there are other problems, welcome to open a new issue.

@xfangfang xfangfang moved this from In progress to Done in Current Work Jan 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
Current Work
  
Done
Development

No branches or pull requests

3 participants