LmeSzinc
commented
2 years ago 还需要当天的gui.txt
Open yzbyzz opened 2 years ago
LmeSzinc
commented
2 years ago 还需要当天的gui.txt
yzbyzz
commented
2 years ago 还需要当天的gui.txt
FYI
═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
START
═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
2022-06-21 00:00:07.857 | INFO | No update
2022-06-21 00:04:15.140 | INFO | End of log queue handler loop
2022-06-21 00:04:15.153 | INFO | [alas_冲绳岛] exited
2022-06-21 00:05:09.356 | INFO | No update
2022-06-21 00:08:25.282 | INFO | Task <Switch_scheduler_btn_refresh (delay=1)> removed.
2022-06-21 00:08:25.289 | INFO | Task <Switch_log_scroll_btn_refresh (delay=1)> removed.
2022-06-21 00:08:25.303 | INFO | Task <alas_update_overiew_task (delay=10)> removed.
2022-06-21 00:08:25.319 | INFO | Task <put_log (delay=0.25)> removed.
2022-06-21 00:08:43.312 | INFO | Add task <Switch_scheduler_btn_refresh (delay=1)>
2022-06-21 00:08:43.345 | INFO | Add task <Switch_log_scroll_btn_refresh (delay=1)>
2022-06-21 00:08:43.363 | INFO | Add task <alas_update_overiew_task (delay=10)>
2022-06-21 00:08:43.374 | INFO | Add task <put_log (delay=0.25)>
2022-06-21 00:10:11.946 | INFO | No update
2022-06-21 00:15:14.680 | INFO | No update
2022-06-21 00:20:16.842 | INFO | No update
2022-06-21 00:25:18.233 | INFO | No update
2022-06-21 00:30:19.528 | INFO | No update
2022-06-21 00:35:20.831 | INFO | No update
2022-06-21 00:40:22.105 | INFO | No update
2022-06-21 00:45:23.299 | INFO | No update
2022-06-21 00:50:24.453 | INFO | No update
2022-06-21 00:55:25.691 | INFO | No update
2022-06-21 01:00:26.882 | INFO | No update
2022-06-21 01:05:28.144 | INFO | No update
2022-06-21 01:10:29.972 | INFO | No update
2022-06-21 01:15:31.214 | INFO | No update
2022-06-21 01:20:32.494 | INFO | No update
2022-06-21 01:25:33.719 | INFO | No update
2022-06-21 01:30:34.984 | INFO | No update
2022-06-21 01:35:36.231 | INFO | No update
2022-06-21 01:40:37.922 | INFO | No update
2022-06-21 01:45:39.184 | INFO | No update
2022-06-21 01:50:40.554 | INFO | No update
2022-06-21 01:55:41.779 | INFO | No update
2022-06-21 02:00:43.183 | INFO | No update
2022-06-21 02:05:44.442 | INFO | No update
2022-06-21 02:10:45.778 | INFO | No update
2022-06-21 02:15:46.998 | INFO | No update
2022-06-21 02:20:48.251 | INFO | No update
2022-06-21 02:25:49.566 | INFO | No update
2022-06-21 02:30:50.777 | INFO | No update
2022-06-21 02:35:52.021 | INFO | No update
2022-06-21 02:41:05.585 | INFO | New update avaliable
2022-06-21 02:41:05.589 | INFO | b1ab1ce0 - Merge pull request #1239 from LmeSzinc/dev
2022-06-21 03:51:07.639 | INFO | Waiting all running alas finish.
2022-06-21 07:49:44.112 | INFO | Task <Switch_scheduler_btn_refresh (delay=1)> removed.
2022-06-21 07:49:44.180 | INFO | Task <Switch_log_scroll_btn_refresh (delay=1)> removed.
2022-06-21 07:49:44.205 | INFO | Task <alas_update_overiew_task (delay=10)> removed.
2022-06-21 07:49:44.209 | INFO | Task <put_log (delay=0.25)> removed.
2022-06-21 07:49:45.173 | INFO | Add task <Switch_updater_refresh (delay=0.5)>
2022-06-21 07:50:21.791 | INFO | Task <Switch_updater_refresh (delay=0.5)> removed.
2022-06-21 07:50:21.799 | INFO | [Server] cn
2022-06-21 07:50:22.016 | INFO | Bind task {'', 'Alas', 'General'}
2022-06-21 07:50:22.675 | INFO | Add task <Switch_scheduler_btn_refresh (delay=1)>
2022-06-21 07:50:22.684 | INFO | Add task <Switch_log_scroll_btn_refresh (delay=1)>
2022-06-21 07:50:22.690 | INFO | Add task <alas_update_overiew_task (delay=10)>
2022-06-21 07:50:22.743 | INFO | Add task <put_log (delay=0.25)>
2022-06-21 07:50:24.316 | INFO | Alas [alas_冲绳岛] stopped
2022-06-21 07:50:24.349 | INFO | Remains: []
2022-06-21 07:50:24.694 | INFO | All alas stopped, start updating
2022-06-21 07:50:24.747 | INFO | <<< RUN UPDATE >>>
2022-06-21 07:50:24.800 | INFO | +---------------------------------------------------+
2022-06-21 07:50:24.850 | INFO | | Update Alas |
2022-06-21 07:50:24.874 | INFO | End of log queue handler loop
2022-06-21 07:50:24.939 | WARNING | Log queue handler thread does not stop within 1 seconds
2022-06-21 07:50:24.949 | INFO | +---------------------------------------------------+
2022-06-21 07:50:25.093 | INFO | [alas_冲绳岛] exited
2022-06-21 07:50:25.115 | INFO | ==================== Git Init ====================
2022-06-21 07:50:25.189 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" init
2022-06-21 07:50:25.547 | INFO | [ success ]
2022-06-21 07:50:25.598 | INFO | ==================== Set Git Proxy ====================
2022-06-21 07:50:25.674 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" config
--local --unset http.proxy
2022-06-21 07:50:25.971 | INFO | [ allowed failure ], error_code: 5
2022-06-21 07:50:26.034 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" config
--local --unset https.proxy
2022-06-21 07:50:26.281 | INFO | [ allowed failure ], error_code: 5
2022-06-21 07:50:26.377 | INFO | ==================== Set Git Repository ====================
2022-06-21 07:50:26.423 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" remote
set-url origin https://gitee.com/LmeSzinc/AzurLaneAutoScript
2022-06-21 07:50:26.695 | INFO | [ success ]
2022-06-21 07:50:26.717 | INFO | ==================== Fetch Repository Branch ====================
2022-06-21 07:50:26.784 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" fetch origin
master
2022-06-21 07:50:27.905 | INFO | [alas_冲绳岛] exited
2022-06-21 07:50:28.323 | INFO | [ success ]
2022-06-21 07:50:28.409 | INFO | ==================== Pull Repository Branch ====================
2022-06-21 07:50:28.447 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" reset --hard
origin/master
2022-06-21 07:50:33.039 | INFO | [ success ]
2022-06-21 07:50:33.054 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" pull
--ff-only origin master
2022-06-21 07:50:33.817 | INFO | Task <Switch_scheduler_btn_refresh (delay=1)> removed.
2022-06-21 07:50:33.844 | INFO | Task <Switch_log_scroll_btn_refresh (delay=1)> removed.
2022-06-21 07:50:33.852 | INFO | Task <alas_update_overiew_task (delay=10)> removed.
2022-06-21 07:50:33.859 | INFO | Task <put_log (delay=0.25)> removed.
2022-06-21 07:50:34.444 | INFO | [ success ]
2022-06-21 07:50:34.463 | INFO | ==================== Show Version ====================
2022-06-21 07:50:34.467 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/Git/mingw64/bin/git.exe" log
--no-merges -1
2022-06-21 07:50:34.647 | INFO | [ success ]
2022-06-21 07:50:34.653 | INFO | +-----------------------------------------------------------+
2022-06-21 07:50:34.659 | INFO | | Update Dependencies |
2022-06-21 07:50:34.673 | INFO | +-----------------------------------------------------------+
2022-06-21 07:50:34.687 | INFO | ==================== Check Python ====================
2022-06-21 07:50:34.699 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/python.exe" --version
2022-06-21 07:50:36.266 | INFO | [ success ]
2022-06-21 07:50:36.272 | INFO | ==================== Update Dependencies ====================
2022-06-21 07:50:36.282 | INFO | "D:/App/AlasApp_0.3.5/AzurLaneAutoScript/toolkit/python.exe" -m pip install -r
requirements.txt -i https://pypi.tuna.tsinghua.edu.cn/simple --disable-pip-version-check
2022-06-21 07:50:36.290 | INFO | Add task <Switch_updater_refresh (delay=0.5)>
2022-06-21 07:50:45.918 | INFO | [ success ]
2022-06-21 07:50:45.961 | INFO | Start clearup
2022-06-21 07:50:45.968 | INFO | [alas_硫磺岛] exited
2022-06-21 07:50:45.979 | INFO | [alas_冲绳岛] exited 补充一些信息，出现问题的环境
做了如下操作，可以稳定复现更新失败的情况。
task_handler.add(updater.schedule_update(), 86400)
task_handler.add(updater.schedule_update(), 5)
th._task.delay = get_next_time(self.schedule_time)
th._task.delay = 5
time.sleep(0.25)
logger.info(f"Remains instances: {_instances}") time.sleep(5)
self.cnt = 0
self.cnt += 1
if self.cnt < 6:
logger.info(f"No update")
return False
else:
logger.info(f"New update avaliable")
return True
- 双击 alas.exe 运行，会撤销本地代码改动。所以使用 console.bat + python gui.py 的方式启动 ALAS。
- 浏览器打开 http://127.0.0.1:22267 ，启动一个调度器。
- 等待 30 秒后，走到更新的流程。
- 同样会卡住。日志如下
```Text
═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
START
═══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
2022-06-24 23:54:53.914 | INFO | New update avaliable
2022-06-24 23:54:53.935 | INFO | Waiting all running alas finish.
2022-06-24 23:54:53.955 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>]
2022-06-24 23:54:58.973 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>]
2022-06-24 23:55:03.999 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>]
2022-06-24 23:55:09.027 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>]
2022-06-24 23:55:14.055 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>] 2022-06-24 23:55:14.277 | INFO | End of log queue handler loop
2022-06-24 23:55:14.290 | INFO | [alas_硫磺岛] exited
2022-06-24 23:55:19.075 | INFO | Alas [alas_硫磺岛] stopped
2022-06-24 23:55:19.095 | INFO | Remains: []
2022-06-24 23:55:19.107 | INFO | Remains instances: []
2022-06-24 23:55:24.118 | INFO | All alas stopped, start updating
2022-06-24 23:55:24.132 | INFO | <<< RUN UPDATE >>> 本问题在 Windows7 上稳定出现，在 Mac 上没有复现。Windows10 待验证。 如果只是 Windows7 的问题，这里建议增加选项控制是否自动更新。 现阶段，我会注释 app.py 里的 task_handler.add(updater.schedule_update(), 86400) 来关闭自动更新。
18870
commented
2 years ago 改成 null 可以禁用自动更新
python -m module.webui.updater 可以直接运行更新部分的代码。
我无法复现这个问题，需要你帮忙对这里debug。
https://github.com/LmeSzinc/AzurLaneAutoScript/blob/7bfff9019ea1740e93cb20ba34b7958230508b2b/module/webui/updater.py#L209-L219
为了打印log这里monkey patch了内置的print函数，不知道是不是这个出了问题
yzbyzz
commented
2 years ago 2022-06-24 23:55:14.055 | INFO | Remains instances: [<module.webui.process_manager.ProcessManager object at
0x000000000C41C388>] 从日志来看，我猜测出问题的地方是在 updater.py 发现有更新，等待所有进程退出的过程中出错。（应该还没到执行更新的步骤。） 这里具体的问题在，ALAS 没有继续执行任务了，但是对应的进程还在运行。 从表现来看就是 ALAS 已经不会执行任务了，但是 Web 页面上 调度器按钮还是处于 “运行”状态，需要手动点击“停止”。 此时 ProcessManager 返回的 running_instances 才会为空，也才会执行后面的更新步骤。
我怀疑 Windows7 下发现更新时，不能正确停止对应的 ProcessManager，所以无法更新。 这里我再做进一步的验证。
18870
commented
2 years ago ~原来不是一个问题~
我发现 exit 只会退出当前线程，尝试在 exit 调用前打印现在存活的进程。
import threading
logger.info(threading.enumerate())INFO 11:48:00.855 │ Update event detected
INFO 11:48:00.858 │ [alas] exited. Reason: Update
INFO 11:48:00.860 │ [<_MainThread(MainThread, started 1181404)>] 结果应该只有一个主线程
yzbyzz
commented
2 years ago 一些验证
在 module/webui/process_manager.py 中增加方法
@classmethod
def show_process(cls):
"""
Show process brief
"""
for process in cls._processes.values():
logger.info(f"[{process}] -> [{process.alive}]")
修改 module/webui/updater.py
def _wait_update(self, instances, names):
if self.state == "cancel":
self.state = 1
self.state = "wait"
self.event.set()
_instances = instances.copy()
while _instances:
for alas in _instances:
if not alas.alive:
_instances.remove(alas)
logger.info(f"Alas [{alas.config_name}] stopped")
logger.info(f"Remains: {[alas.config_name for alas in _instances]}")
if self.state == "cancel":
self.state = 1
self.event.clear()
ProcessManager.restart_processes(instances, self.event)
return
# >>>>>>>>>>>>>>>>>>>>>
logger.info(f"running instances: {_instances}")
ProcessManager.show_process()
time.sleep(5)
# <<<<<<<<<<<<<<<<<<<<<
self._run_update(instances, names)
可以看到发现更新后，日志如下
2022-06-25 10:19:11.153 | INFO | [<module.webui.process_manager.ProcessManager object at 0x1146a17d0>] -> [True] 在浏览器中手动点击“停止”按钮后，日志如下
2022-06-25 10:20:11.153 | INFO | [<module.webui.process_manager.ProcessManager object at 0x1146a17d0>] -> [False] 此时才会开始执行更新的步骤。
发现更新后，日志如下，（不需要手动点击“停止”按钮，就会执行更新）
2022-06-25 10:29:11.153 | INFO | [<module.webui.process_manager.ProcessManager object at 0x1146a17d0>] -> [False] Windows7 下 is_alive 判断不准确？ https://github.com/LmeSzinc/AzurLaneAutoScript/blob/7bfff9019ea1740e93cb20ba34b7958230508b2b/module/webui/process_manager.py?_pjax=%23js-repo-pjax-container#L79-L84
从下面几篇链接来看，process kill 后的一段时间内 is_alive 仍然可能为 true。
但是目前的检查进程结束，是一个循环判断，这样看来 is_alive 应该是一直返回 true。 所以问题是否在于目前进程退出的方式 exit 在 Windows7 下不生效？ https://github.com/LmeSzinc/AzurLaneAutoScript/blob/7bfff9019ea1740e93cb20ba34b7958230508b2b/alas.py#L339-L341
yzbyzz
commented
2 years ago ...
INFO 11:48:00.855 │ Update event detected INFO 11:48:00.858 │ [alas] exited. Reason: Update INFO 11:48:00.860 │ [<_MainThread(MainThread, started 1181404)>]结果应该只有一个主线程
Windows7 下打印线程，结果相同，只有一个线程
2022-06-25 12:45:45.609 | INFO | Update event detected
2022-06-25 12:45:45.634 | INFO | [alas_硫磺岛] exited. Reason: Update
2022-06-25 12:45:45.647 | INFO | [<_MainThread(MainThread, started 2388)>] 重新跑了一次，日志比较清晰一点。
12:51:40 gui 发现更新，等待所有 alas 停止
// gui.txt
2022-06-25 12:51:40.473 | INFO | >>>> _chec_update, cnt:7
2022-06-25 12:51:40.498 | INFO | New update avaliable
2022-06-25 12:51:40.512 | INFO | Waiting all running alas finish.
2022-06-25 12:51:40.524 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 1] >>>
2022-06-25 12:51:40.543 | INFO | process[<module.webui.process_manager.ProcessManager object at 0x000000000C206D88>]
[alas_硫磺岛] -> [True]
2022-06-25 12:51:40.577 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 1] >>> 12:51:44 alas 发现更新，停止自身
// alas.txt
2022-06-25 12:51:44.292 | INFO | Update event detected
2022-06-25 12:51:44.324 | INFO | [alas_硫磺岛] exited. Reason: Update
2022-06-25 12:51:44.344 | INFO | [<_MainThread(MainThread, started 6992)>] 从 gui 的视角，alas 还没有停止，继续循环等待。（且将一直等待下去，除非人为停止。）
// gui.txt
2022-06-25 12:52:00.868 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>>
2022-06-25 12:52:00.886 | INFO | process[<module.webui.process_manager.ProcessManager object at 0x000000000C206D88>]
[alas_硫磺岛] -> [True]
2022-06-25 12:52:00.915 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>> // gui.txt
2022-06-25 12:52:05.940 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>>
2022-06-25 12:52:05.957 | INFO | process[<module.webui.process_manager.ProcessManager object at 0x000000000C206D88>]
[alas_硫磺岛] -> [True]
2022-06-25 12:52:05.983 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>> // gui.txt
2022-06-25 12:52:39.124 | INFO | End of log queue handler loop
2022-06-25 12:52:39.147 | INFO | [alas_硫磺岛] exited
2022-06-25 12:52:41.434 | INFO | Alas [alas_硫磺岛] stopped
2022-06-25 12:52:41.453 | INFO | Remains: []
2022-06-25 12:52:41.469 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>>
2022-06-25 12:52:41.481 | INFO | process[<module.webui.process_manager.ProcessManager object at 0x000000000C206D88>]
[alas_硫磺岛] -> [False]
2022-06-25 12:52:41.513 | INFO | <<< SHOW_PROCESSES, TAG[_WAIT_UPDATE 2] >>>
2022-06-25 12:52:46.533 | INFO | All alas stopped, start updating
2022-06-25 12:52:46.545 | INFO | <<< RUN UPDATE >>>
2022-06-25 12:52:46.571 | INFO | <<< MOCK UPDATE >>>
2022-06-25 12:52:46.584 | INFO | Start clearup
2022-06-25 12:52:46.614 | INFO | [alas_硫磺岛] exited 试试这个
from multiprocessing import Process
import os
import time
def sysexit():
print("Run sysexit function")
time.sleep(3)
print("Call exit")
exit(0)
print("sysexit finish")
def osexit():
print("Run osexit function")
time.sleep(3)
print("Call exit")
os._exit(0)
print("osexit finish")
def run(p: Process):
p.start()
for _ in range(5):
time.sleep(1)
print(p.is_alive())
print("Kill process")
p.kill()
time.sleep(1)
print(p.is_alive())
if __name__ == "__main__":
ps = Process(target=sysexit)
po = Process(target=osexit)
run(ps)
run(po)
Run sysexit function
True
True
True
Call exit
False
False
Kill process
False
Run osexit function
True
True
True
Call exit
False
False
Kill process
False项目中两个停止进程的路径，除了使用的方法不同，两者对应的脚本也是不同的。
yzbyzz
commented
2 years ago 看到有两种停止的方式
这里可能应该统一一下退出的方式？
18870
commented
2 years ago 发现更新的时候需要等alas完成任务自己退出，否则可能会卡在某个页面无法再启动。 正常情况下都能自己退出，没有必要跨进程通信让父进程把子进程杀了
你这个我确实想不到什么情况了，摆了
yzbyzz
commented
2 years ago 我先按照上面提到的修改配置文件来禁止自动更新吧。 目前看来可能遇到这个问题的人不多，先暂时这样吧。 后面再看看能不能找到原因。
LostMyMind
commented
2 years ago 我的Windows7也同样遇到了此问题。一开始还以为是网络波动导致的。
在提问之前...
描述你的问题
当 ALAS 发现有更新的时候，会停止执行任务。 但是没有执行更新操作，也没有继续执行任务。
如何复现
预期行为
希望在发现更新后
相关 Logs
截图
No response
还有别的吗？
一些猜测： （日志里没有看到相关的信息加以验证，仅做参考）