Repository navigation
Image not returned to chat or folder with 2FA enabled #181
Description
Activity
[401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities>That's very strange. Does AppAPI is the last version or at least
1.4.3version?AppAPI is at version 1.4.4
Nextcloud log file will be very useful here, you can archive it and attach here or send it me to bigcat88@icloud.com if it is contain some data that you do not want to share to public.
And can you say what Internet connection speed do you have?
- Have you tried to re-install/re-enable ExApp?
- Could you send us rows from the
ex_apps_api_scopestable, andex_apps_scopestable to verify all required scopes are granted, missing scope might lead to 401 unauthorized error.
And yeah, check the logs for any additional info could be helpful.
@bigcat88 For logs, my logs are flooded with entries from the this GroupFolder problem, but from what I'm seeing, only the 401 error pops up in there.
- Disabled, removed, reinstalled. Seems I don't have the 401 error anymore, but no image.
TRACE: 172.18.0.8:56100 - HTTP connection made TRACE: 172.18.0.8:56100 - ASGI [5] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 14612), 'client': ('172.18.0.8', 56100), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.8:56100 - ASGI [5] Receive {'type': 'http.request', 'body': '<332 bytes>', 'more_body': False} TRACE: 172.18.0.8:56100 - ASGI [5] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} INFO: 172.18.0.8:56100 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.8:56100 - ASGI [5] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.8:56100 - ASGI [5] Completed task added loading model Loading pipeline components...: 0%| | 0/7 [00:00<?, ?it/s]TRACE: 172.18.0.8:56100 - HTTP connection lost Loading pipeline components...: 100%|██████████| 7/7 [00:02<00:00, 2.60it/s] model loaded: 2.699454173911363s generating image 100%|██████████| 1/1 [00:09<00:00, 9.36s/it]> nextcloud_database=> select * from oc_ex_apps_scopes; > id | appid | scope_group > ----+------------------------+------------- > 1 | ai_image_generator_bot | 60 > 2 | ai_image_generator_bot | 10 > 3 | ai_image_generator_bot | 11 > 4 | ai_image_generator_bot | 50 > (4 rows) > id | appid | version | name | daemon_config_name | protocol | host | port | secret | status | enabled | created_time | last_check_time ----+------------------------+---------+---------------------+--------------------+----------+------------------------+-------+----------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+---------+--------------+----------------- 2 | ai_image_generator_bot | 1.0.1 | AIImageGeneratorBot | docker_aio | http | ai_image_generator_bot | 14612 | DhLszv+ZSvb+AJL7581y/lm9sEJUCmkEXVAG4kS6GzH7Nv59TFgKfoxYriY6DqDxZDymLg44dMYelZXLQl5/g60/CRG5KDUtMBj44egQ9p7n6bQekmRDpiXJrIHfZWXS | {"active":true,"init_start_time":1703362910} | 1 | 1703362910 | 1703362913and no string "image generated:" in bot container log?
it should be after Image is generatedif no such string then it is bug of a bot, I'll try to fix this in a few days and publish a new release
May I ask how much RAM is allowed for a Docker container? (on the CPU the bot can eat up to 18 gig maximum)
Did a new @ image, here are the logs. The "
image generated" log is there, and the 401 is back.TRACE: 172.18.0.8:36610 - HTTP connection made TRACE: 172.18.0.8:36610 - ASGI [7] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 14612), 'client': ('172.18.0.8', 36610), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.8:36610 - ASGI [7] Receive {'type': 'http.request', 'body': '<332 bytes>', 'more_body': False} TRACE: 172.18.0.8:36610 - ASGI [7] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} image generated: 27.15990306797903s [401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities> INFO: 172.18.0.8:36610 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.8:36610 - ASGI [7] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.8:36610 - ASGI [7] Completed TRACE: 172.18.0.8:36610 - HTTP connection lost task added generating image 100%|██████████| 1/1 [00:07<00:00, 7.99s/it]Mind you, it says 27.x s, which I assume should mean an elapse time, but this is instant. There's no delay and nothing takes 27 seconds.
There's a sligh pause pause between "
TRACE: 172.18.0.8:36610 - HTTP connection lost" and "task added", about 1-2 seconds. Then after "generating image" it seems to take about the time it says, 7.99 seconds in the case of the previous log.For RAM, it seems it's allowed to take as much as it wants. There's 64G on the VM.
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 9cd4c1f74f09 nc_app_ai_image_generator_bot 0.23% 1.332GiB / 62.79GiB 2.12% 221kB / 146kB 0B / 770kB 25There's a big spike in CPU with an @ image call, but the memory barely changes. Shouldn't it be taking 13GiB?
ONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 9cd4c1f74f09 nc_app_ai_image_generator_bot 667.62% 1.338GiB / 62.79GiB 2.13% 255kB / 166kB 0B / 770kB 25When the container starts, the first @ image call will generate different logs than subsequent calls.
Startup:
INFO: Started server process [1] INFO: Waiting for application startup. TRACE: ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}, 'state': {}} TRACE: ASGI [1] Receive {'type': 'lifespan.startup'} TRACE: ASGI [1] Send {'type': 'lifespan.startup.complete'} INFO: Application startup complete. INFO: Uvicorn running on http://0.0.0.0:14612 (Press CTRL+C to quit)First call:
TRACE: 172.18.0.8:36424 - HTTP connection made TRACE: 172.18.0.8:36424 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 14612), 'client': ('172.18.0.8', 36424), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.8:36424 - ASGI [2] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False} TRACE: 172.18.0.8:36424 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} INFO: 172.18.0.8:36424 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.8:36424 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.8:36424 - ASGI [2] Completed TRACE: 172.18.0.8:36424 - HTTP connection lost task added loading model Loading pipeline components...: 100%|██████████| 7/7 [00:03<00:00, 1.80it/s] model loaded: 3.90906948199995s generating image 100%|██████████| 1/1 [00:27<00:00, 27.27s/it]Second and future calls:
TRACE: 172.18.0.8:48288 - HTTP connection made TRACE: 172.18.0.8:48288 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 14612), 'client': ('172.18.0.8', 48288), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.8:48288 - ASGI [3] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False} TRACE: 172.18.0.8:48288 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} TRACE: 172.18.0.8:48288 - ASGI [3] Send {'type': 'http.response.body', 'body': '<0 bytes>'} image generated: 50.36925267000015s [401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities> INFO: 172.18.0.8:48288 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.8:48288 - ASGI [3] Completed TRACE: 172.18.0.8:48288 - HTTP connection lost task added generating image 100%|██████████| 1/1 [00:05<00:00, 5.04s/it]You're not getting the "
image generated" in the first call, and there's also no 401 error.I'm not a developer, but I figured I could try to help find where things are going wrong by adding a few print messages. I modified the while True loop at line 73. I added a counter (i) and messages along the code with the counter to see in which iteration it would trigger.
while True: try: + i += 1 task: TalkBotMessage = TASK_LIST.get(block=True, timeout=60 * 60) if PIPE is None: print("loading model") time_start = perf_counter() PIPE = AutoPipelineForText2Image.from_pretrained( snapshot_download( MODEL_NAME, local_files_only=True, cache_dir=persistent_storage(), ), **MODEL_RUNTIME_OPT, ) if torch.cuda.is_available(): PIPE.to("cuda") elif torch.backends.mps.is_available(): PIPE.to("mps") print(f"model loaded: {perf_counter() - time_start}s") r = re.search(r"@image\s(.*)", task.object_content["message"], re.IGNORECASE) + print(f"{i} generating image") - print(f"generating image") time_start = perf_counter() im = PIPE(prompt=r.group(1), num_inference_steps=1, guidance_scale=0.0).images[0] # mypy + print(f"{i} image generated: {perf_counter() - time_start}s") - print(f"image generated: {perf_counter() - time_start}s") + print(f"{i} nc =") nc = NextcloudApp() + print(f"{i} nc.set") nc.set_user(task.actor_id[len("users/") :]) + print(f"{i} nc.files") nc.files.makedirs("image_generator_bot", exist_ok=True) + print(f"{i} im_out") im_out = io.BytesIO() + print(f"{i} im.save") im.save(im_out, format="PNG") + print(f"{i} im_out2") im_out.seek(0) + print(f"{i} new_im") new_im = nc.files.upload_stream( f"image_generator_bot/{datetime.now().strftime('%Y-%m-%d-%H-%M-%S.%f')}.png", im_out, ) nc.talk.send_file(new_im, task.conversation_token) im = nc = im_out = None # noqa except queue.Empty: if PIPE: print("offloading model") PIPE = None except Exception as e: # noqa print(str(e)) NextcloudApp().log(LogLvl.ERROR, str(e))With this, the log looks like this:
Startup:
INFO: Started server process [1] INFO: Waiting for application startup. TRACE: ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}, 'state': {}} TRACE: ASGI [1] Receive {'type': 'lifespan.startup'} TRACE: ASGI [1] Send {'type': 'lifespan.startup.complete'} INFO: Application startup complete. INFO: Uvicorn running on http://0.0.0.0:16919 (Press CTRL+C to quit)First @ image call:
TRACE: 172.18.0.7:35026 - HTTP connection made TRACE: 172.18.0.7:35026 - ASGI [2] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 16919), 'client': ('172.18.0.7', 35026), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.7:35026 - ASGI [2] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False} TRACE: 172.18.0.7:35026 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} INFO: 172.18.0.7:35026 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.7:35026 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.7:35026 - ASGI [2] Completed TRACE: 172.18.0.7:35026 - HTTP connection lost task added loading model Loading pipeline components...: 100%|██████████| 7/7 [00:01<00:00, 3.57it/s] model loaded: 1.972439844001201s 1 generating image 100%|██████████| 1/1 [00:09<00:00, 9.38s/it]Second call:
TRACE: 172.18.0.7:48178 - HTTP connection made TRACE: 172.18.0.7:48178 - ASGI [3] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 16919), 'client': ('172.18.0.7', 48178), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.7:48178 - ASGI [3] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False} TRACE: 172.18.0.7:48178 - ASGI [3] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} 1 image generated: 26.7607214929958s 1 nc = 1 nc.set [401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities> INFO: 172.18.0.7:48178 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.7:48178 - ASGI [3] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.7:48178 - ASGI [3] Completed TRACE: 172.18.0.7:48178 - HTTP connection lost task added 2 generating image 100%|██████████| 1/1 [00:07<00:00, 7.76s/it]So we can see the first call's last line executed seems to be
im = PIPE(prompt=r.group(1), num_inference_steps=1, guidance_scale=0.0).images[0] # mypyas I'm assuming this is what generates the100%|██████████| 1/1 [00:09<00:00, 9.38s/it]line, but it goes no further.Then on the second call, 3 lines from the first call get executed:
print(f"image generated: {perf_counter() - time_start}s") nc = NextcloudApp() nc.set_user(task.actor_id[len("users/") :])And then it goes until the same
im = PIPE(prompt=r.group(1), num_inference_steps=1, guidance_scale=0.0).images[0] # mypyline again. I tried to include something to save the image to local file right after this to see if it actually generates, but didn't get that working.I don't know if this is useful. Again, not a developer. Let me know if there's something you'd like me to try.
uh, if you want to help, you can help with something.
looks like you knows how to edit code inside container, so you can try this:
im = PIPE(prompt=r.group(1), num_inference_steps=1, guidance_scale=0.0).images[0] print(f"image generated: {perf_counter() - time_start}s") im.save("test.png") # **add this line**
after that probably after a first run or a second one, after "image generated" message you will see a new file inside container, probably in
/app/libdirectory in container that file should be present.Interesting to know, if it will be present or not.
I haven’t had time to deal with this issue yet, but I will very soon
It did create the file after the first call. It took a bit of time after the
100%|██████████| 1/1 [00:07<00:00, 8.00s/it]line, like 10 seconds or so, but it did create it. Oddly, the "image generated" log entry didn't show up until after the second call.root@ai_image_generator_bot:/app/lib# ls -la total 324 drwxr-xr-x 1 root root 4096 Dec 24 16:12 . drwxr-xr-x 1 root root 4096 Dec 17 21:39 .. drwxr-xr-x 1 root root 4096 Dec 24 16:10 __pycache__ -rw-r--r-- 1 root root 5403 Dec 24 16:10 main.py -rw-r--r-- 1 root root 302103 Dec 24 16:11 test.pngthanks a lot for testing, give me one day, I hope I will be able tomorrow to publish new docker image with bot, and I will ping here with ask for test
I am still can not understand, how it can create file, but can not print to console after that.
Can you try with
print(..., flush=True)
3 remaining items
I do not know how it is possible, it is enabled and fine.
/ocs/v1.php/cloud/capabilitiesis a basic route for AppAPI, all ExApps can call it.any ideas how we can investigate this @andrey18106 ? Maybe make more logging in AppAPI?
For logs, my logs are flooded with entries from the this GroupFolder problem, but from what I'm seeing, only the 401 error pops up in there.
Logs will help us, we can deal with spam fine, we use
jqfor logs analyze. If they will not help we will release new AppAPI with more logs...I sent you the logs via emails. I did find a few notable entries.
{"reqId":"wsQ4qoqDjf3eGfOAJCsg","level":3,"time":"2023-12-24T17:38:26+00:00","remoteAddr":"172.18.0.1","user":"--","app":"app_api","method":"GET","url":"/login/selectchallenge?redirect_url=%2Focs%2Fv1.php%2Fcloud%2Fcapabilities?format%253Djson","message":"Failed to check apiScope /login/selectchallenge","userAgent":"python-httpx/0.25.2","version":"27.1.5.1","data":{"app":"app_api"}} {"reqId":"cgEIAVjb7k6L7vYfUg4Q","level":3,"time":"2023-12-24T17:38:27+00:00","remoteAddr":"172.18.0.1","user":"--","app":"ai_image_generator_bot","method":"POST","url":"/ocs/v1.php/apps/app_api/api/v1/log?format=json","message":"[401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities>","userAgent":"python-httpx/0.25.2","version":"27.1.5.1","data":{"app":"ai_image_generator_bot"}}These seem to appear when I make calls.
Reacted by Alexander Piskundo you have twofactor_webauthn installed?
as I understand it is this app addsselectchallengeto the url?I don't, see list below. But I do have "Enforce two-factor authentication" enabled.
Enabled: - activity: 2.19.0 - admin_audit: 1.17.0 - app_api: 1.4.4 - bruteforcesettings: 2.7.0 - calendar: 4.6.1 - camerarawpreviews: 0.8.4 - circles: 27.0.1 - cloud_federation_api: 1.10.0 - comments: 1.17.0 - contacts: 5.5.0 - contactsinteraction: 1.8.0 - dav: 1.27.0 - facerecognition: 0.9.31 - federatedfilesharing: 1.17.0 - files: 1.22.0 - files_external: 1.19.0 - files_pdfviewer: 2.8.0 - files_reminders: 1.0.0 - files_rightclick: 1.6.0 - files_sharing: 1.19.0 - files_trashbin: 1.17.0 - files_versions: 1.20.0 - groupfolders: 15.3.2 - impersonate: 1.14.0 - logreader: 2.12.0 - lookup_server_connector: 1.15.0 - memories: 6.1.5 - metadata: 0.19.0 - nextcloud-aio: 0.4.0 - notes: 4.9.1 - notifications: 2.15.0 - notify_push: 0.6.6 - oauth2: 1.15.1 - password_policy: 1.17.0 - passwords: 2023.12.31 - photos: 2.3.0 - previewgenerator: 5.4.0 - privacy: 1.11.0 - provisioning_api: 1.17.0 - recognize: 5.0.3 - related_resources: 1.2.0 - serverinfo: 1.17.0 - settings: 1.9.0 - sharebymail: 1.17.0 - side_menu: 3.11.2 - spreed: 17.1.4 - support: 1.10.0 - suspicious_login: 5.0.0 - systemtags: 1.17.0 - text: 3.8.0 - theming: 2.2.0 - theming_customcss: 1.15.0 - twofactor_backupcodes: 1.16.0 - twofactor_totp: 9.0.0 - unsplash: 2.2.1 - user_status: 1.7.0 - viewer: 2.1.0 - welcome: 1.0.10 - workflowengine: 2.9.0 Disabled: - dashboard: 7.7.0 (installed 7.5.0) - encryption: 2.15.0 - federation: 1.17.0 (installed 1.15.0) - firstrunwizard: 2.16.0 (installed 2.14.0) - nextcloud_announcements: 1.16.0 (installed 1.14.0) - recommendations: 1.6.0 (installed 1.4.0) - survey_client: 1.15.0 (installed 1.13.0) - user_ldap: 1.17.0 - weather_status: 1.7.0 (installed 1.5.0)To test, I changed the forced 2FA inclusion/exclusion logic around and only included real user groups. Still the 401. I also then tried to disable the enforcement, still the 401.
!!
I disabled 2FA on my account entirely and this works now.
Reacted by Andrey Borysenko and Alexander PiskunThanks man, you found a critical bug in AppAPI related to 2FA.
We will fix this as soon as possible(in this year)- changed the title
[-]Image not returned to chat or folder[/-][+]Image not returned to chat or folder with 2FA enabled[/+]on Dec 24, 2023 - added a commit that references this issue
on Dec 27, 2023 @MrNunu Thank you again for informing. Fix in server will be included starting from Nextcloud 27.1.6 (nextcloud/server#42520)
Installed this on AIO 7.9.0 (Nextcloud 27.1.5) and while the logs seem to show the app responds to @image prompt, I'm not getting an image back either in chat or in the folder.
I do see the 401 error in there but unsure how to deal with it.
Here are some screenshots showing what I think is a successful installation.