search

nextcloud / app_api

Nextcloud AppAPI
https://apps.nextcloud.com/apps/app_api
GNU Affero General Public License v3.0
71 stars 6 forks source link

Image not returned to chat or folder with 2FA enabled #181

Closed MrNunu closed 8 months ago

MrNunu commented 9 months ago

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.

TRACE: 172.18.0.8:35626 - HTTP connection made TRACE: 172.18.0.8:35626 - ASGI [12] Started scope={'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('172.18.0.11', 15888), 'client': ('172.18.0.8', 35626), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''} TRACE: 172.18.0.8:35626 - ASGI [12] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False} TRACE: 172.18.0.8:35626 - ASGI [12] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'} image generated: 22.71879433398135s [401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities> offloading model INFO: 172.18.0.8:35626 - "POST /stable_diffusion HTTP/1.1" 200 OK TRACE: 172.18.0.8:35626 - ASGI [12] Send {'type': 'http.response.body', 'body': '<0 bytes>'} TRACE: 172.18.0.8:35626 - ASGI [12] Completed task added loading model Loading pipeline components...: 14%|█▍ | 1/7 [00:00<00:04, 1.41it/s]TRACE: 172.18.0.8:35626 - HTTP connection lost Loading pipeline components...: 100%|██████████| 7/7 [00:02<00:00, 2.84it/s] model loaded: 2.475664479075931s generating image 100%|██████████| 1/1 [00:08<00:00, 8.17s/it]

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.

image

image

image

bigcat88 commented 9 months ago

[401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities>

That's very strange. Does AppAPI is the last version or at least 1.4.3 version?

MrNunu commented 9 months ago

AppAPI is at version 1.4.4

bigcat88 commented 9 months ago

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?

andrey18106 commented 9 months ago

@MrNunu

  1. Have you tried to re-install/re-enable ExApp?
  2. Could you send us rows from the ex_apps_api_scopes table, and ex_apps_scopes table 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.

MrNunu commented 9 months ago

@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.

@andrey18106,

  1. 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 |      1703362913
bigcat88 commented 9 months ago

and no string "image generated:" in bot container log? it should be after Image is generated

ref: https://github.com/cloud-py-api/ai_image_generator_bot/blob/2084081a4d877b3254a894b90aeef9b3afa6ec8f/lib/main.py#L96

bigcat88 commented 9 months ago

if 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

bigcat88 commented 9 months ago

May I ask how much RAM is allowed for a Docker container? (on the CPU the bot can eat up to 18 gig maximum)

MrNunu commented 9 months ago

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        25
MrNunu commented 9 months ago

There'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   25
MrNunu commented 9 months ago

When 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.

MrNunu commented 9 months ago

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] # mypy as I'm assuming this is what generates the 100%|██████████| 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] # mypy line 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.

bigcat88 commented 9 months ago

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/lib directory 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

MrNunu commented 9 months ago

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.png
bigcat88 commented 9 months ago

thanks 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)
MrNunu commented 9 months ago

No problem on the delay. You can ignore me while I try things out. I appreciate the project as well as your time troubleshooting.

That did something. The log entry showed up correctly after the save in the first call. I modified my own print commands and we seem to be stopping after nc = NextcloudApp(). I also modified exception print and we're getting the 401 error right after that.


TRACE:    172.18.0.7:53948 - HTTP connection made
TRACE:    172.18.0.7:53948 - 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', 53948), 'scheme': 'http', 'root_path': '', 'headers': '<...>', 'state': {}, 'method': 'POST', 'path': '/stable_diffusion', 'raw_path': b'/stable_diffusion', 'query_string': b''}
TRACE:    172.18.0.7:53948 - ASGI [2] Receive {'type': 'http.request', 'body': '<322 bytes>', 'more_body': False}
TRACE:    172.18.0.7:53948 - ASGI [2] Send {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO:     172.18.0.7:53948 - "POST /stable_diffusion HTTP/1.1" 200 OK
TRACE:    172.18.0.7:53948 - ASGI [2] Send {'type': 'http.response.body', 'body': '<0 bytes>'}
TRACE:    172.18.0.7:53948 - ASGI [2] Completed
TRACE:    172.18.0.7:53948 - HTTP connection lost
task added
loading model
Loading pipeline components...: 100%|██████████| 7/7 [00:01<00:00,  3.73it/s]
model loaded: 1.886813498000265s
1 generating image
100%|██████████| 1/1 [00:09<00:00,  9.23s/it]
1 image generated: 27.27185331999499s
1 nc =
1 nc.set
[401] Unauthorized <request: GET /ocs/v1.php/cloud/capabilities>
bigcat88 commented 9 months ago

that's very cool, this info is really very useful now.

Please post oc_ex_apps records, we are interesting in the "status" field.

And cutoff "secret" from record before posting here if it is a production instance with Internet

MrNunu commented 9 months ago 
 id |         appid          | version |        name         | daemon_config_name | protocol |          host          | port  |                                                              secret                                                              |                    status                    | enabled | created_time | last_check_time
----+------------------------+---------+---------------------+--------------------+----------+------------------------+-------+----------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------+---------+--------------+-----------------
  3 | ai_image_generator_bot | 1.0.1   | AIImageGeneratorBot | docker_aio         | http     | ai_image_generator_bot | 16919 | ******************************************************************************************************************************** | {"active":true,"init_start_time":1703389869} |       1 |   1703389869 |      1703390140
bigcat88 commented 9 months ago

I do not know how it is possible, it is enabled and fine. /ocs/v1.php/cloud/capabilities is a basic route for AppAPI, all ExApps can call it.

any ideas how we can investigate this @andrey18106 ? Maybe make more logging in AppAPI?

bigcat88 commented 9 months ago

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 jq for logs analyze. If they will not help we will release new AppAPI with more logs...

MrNunu commented 9 months ago

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.

bigcat88 commented 9 months ago

do you have twofactor_webauthn installed? as I understand it is this app adds selectchallenge to the url?

MrNunu commented 9 months ago

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)
MrNunu commented 9 months ago

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.

MrNunu commented 9 months ago

image

!!

I disabled 2FA on my account entirely and this works now.

bigcat88 commented 9 months ago

Thanks man, you found a critical bug in AppAPI related to 2FA. We will fix this as soon as possible(in this year)

andrey18106 commented 8 months ago

@MrNunu Thank you again for informing. Fix in server will be included starting from Nextcloud 27.1.6 (https://github.com/nextcloud/server/pull/42520)