search

UP-NextPush / server-app

UnifiedPush provider for Nextcloud - server application - Moved to https://codeberg.org/NextPush/uppush
GNU Affero General Public License v3.0
67 stars 8 forks source link

array_key_exists #8

Closed Tealk closed 2 years ago

Tealk commented 2 years ago

Hello

I see several times in my log the following error message:

{"reqId":"GVAqi9xoqVDhdl1bU8nM","level":3,"time":"01.03.2022 14:04:20","remoteAddr":"93.212.25.232","user":"--","app":"index","method":"GET","url":"/index.php/apps/uppush/device/1d6cf04d-4ae8-492f-a892-50f133b8e1e5","message":"array_key_exists(): Argument #2 ($array) must be of type array, null given in file 'WEBPATH/lib/public/AppFramework/Controller.php' line 121","userAgent":"okhttp/4.9.3","version":"23.0.2.1","exception":{"Exception":"Exception","Message":"array_key_exists(): Argument #2 ($array) must be of type array, null given in file 'WEBPATH/lib/public/AppFramework/Controller.php' line 121","Code":0,"Trace":[{"file":"WEBPATH/lib/private/AppFramework/App.php","line":157,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"WEBPATH/lib/private/Route/Router.php","line":302,"function":"main","class":"OC\\AppFramework\\App","type":"::"},{"file":"WEBPATH/lib/base.php","line":1006,"function":"match","class":"OC\\Route\\Router","type":"->"},{"file":"WEBPATH/index.php","line":36,"function":"handleRequest","class":"OC","type":"::"}],"File":"WEBPATH/lib/private/AppFramework/Http/Dispatcher.php","Line":158,"Previous":{"Exception":"TypeError","Message":"array_key_exists(): Argument #2 ($array) must be of type array, null given","Code":0,"Trace":[{"file":"WEBPATH/lib/public/AppFramework/Controller.php","line":121,"function":"array_key_exists"},{"file":"WEBPATH/lib/private/AppFramework/Http/Dispatcher.php","line":228,"function":"getResponderByHTTPHeader","class":"OCP\\AppFramework\\Controller","type":"->"},{"file":"WEBPATH/lib/private/AppFramework/Http/Dispatcher.php","line":126,"function":"executeController","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"WEBPATH/lib/private/AppFramework/App.php","line":157,"function":"dispatch","class":"OC\\AppFramework\\Http\\Dispatcher","type":"->"},{"file":"WEBPATH/lib/private/Route/Router.php","line":302,"function":"main","class":"OC\\AppFramework\\App","type":"::"},{"file":"WEBPATH/lib/base.php","line":1006,"function":"match","class":"OC\\Route\\Router","type":"->"},{"file":"WEBPATH/index.php","line":36,"function":"handleRequest","class":"OC","type":"::"}],"File":"WEBPATH/lib/public/AppFramework/Controller.php","Line":121},"CustomMessage":"--"}}

[Nextcloud Hub II] 23.0.2 Unified Push Provider 0.2.1

p1gp1g commented 2 years ago

It happens when your client reconnect when the old connection is not nicely closed. I keep this issue open to remember to catch this error.

PS: You should logout/login your client again since you forgot to redact some sensitive information (like the device_id uuid)

Tealk commented 2 years ago

PS: You should logout/login your client again since you forgot to redact some sensitive information (like the device_id uuid)

Where can I delete something like that?

//Edit Have now done this with the nextpush, but now no app is registered with nextpush :'( Do I now have to reinstall all apps so that they register again?

p1gp1g commented 2 years ago

Opening the previously registered app should register again

Tealk commented 2 years ago

Opening the previously registered app should register again

So at schildichat there was a button to re-register, the rest I haven't managed yet.

Tealk commented 2 years ago

i logged out of the app like you said and logged in again, I still get the error message every 3 minutes

p1gp1g commented 2 years ago

Logging out was to change the token you pasted here. This token is meant to be secret.

This error is when the application reconnects, I'll catch it to avoid misunderstanding.

But you should not have this error every 3 mintues. Did you set correctly your reverse proxy ? https://github.com/UP-NextPush/server-app#installation pt 2

Tealk commented 2 years ago

But you should not have this error every 3 mintues. Did you set correctly your reverse proxy ? https://github.com/UP-NextPush/server-app#installation pt 2

is this also relevant if i don't use a proxy at all to access the nexcloud installation?

p1gp1g commented 2 years ago

There might be a reverse proxy under the hood. How have you installed nextcloud ?

Tealk commented 2 years ago

I just set up a normal Nginx webserver, put the archive files in the web folder and then called the installation script.

I do not see where there is a proxy at work, because nextcloud is delivered via php-fpm

p1gp1g commented 2 years ago

You very probably have to change fastcgi config [1] instead of proxy ones

Feedback is welcome to update the readme :)

[1] https://nginx.org/en/docs/http/ngx_http_fastcgi_module.html

Tealk commented 2 years ago

You very probably have to change fastcgi config [1] instead of proxy ones

Is there a location to which I can restrict the timeout? Like for example here:

location ^~ /uppush/ {
    fastcgi_connect_timeout   10m;
    fastcgi_send_timeout      10m;
    fastcgi_read_timeout      10m;
}
p1gp1g commented 2 years ago

/index.php/apps/uppush/

Tealk commented 2 years ago

Feedback is welcome to update the readme :)

How can I see if the setting is effective?

p1gp1g commented 2 years ago

You should not have the error every 3 min :)

p1gp1g commented 2 years ago

You may need to add the following too

fastcgi_buffering off;
Tealk commented 2 years ago

Well, that should be obvious right away, seems to have been the case even more often. grafik

my current setting, in a few minutes we'll see if it works

location /index.php/apps/uppush/ {
    fastcgi_buffering off;
    fastcgi_connect_timeout   10m;
    fastcgi_send_timeout      10m;
    fastcgi_read_timeout      10m;
}
Tealk commented 2 years ago

I guess it didn't quite work out that way grafik

p1gp1g commented 2 years ago

I guess you have reloaded your nginx.

Do you have android logs too ? 

adb logcat --pid=(adb shell pidof -s org.unifiedpush.distributor.nextpush)

You may have to redact some tokens

Tealk commented 2 years ago

yes nginx has been reloaded several times

i can only send the log later when i am at my private computer

this token has the following format? "1d6cf04d-4ae8-492f-a892-50f133b8e1e5"

p1gp1g commented 2 years ago

Yes, that's an UUIDv4 token

Tealk commented 2 years ago

i have installed the "android-udev" package but supposedly the system does not know the adb command https://wiki.archlinux.org/title/Android_Debug_Bridge must first find out how the whole thing works

also i think you forgot a dollar in the command for the pid adb logcat --pid=$(adb shell pidof -s org.unifiedpush.distributor.nextpush)

p1gp1g commented 2 years ago

That's the android-tools package.

also i think you forgot a dollar in the command for the pid adb logcat --pid=$(adb shell pidof -s org.unifiedpush.distributor.nextpush)

That's because I use fish, sorry x)

Tealk commented 2 years ago

Here the log:

--------- beginning of main
03-04 18:00:54.061 23542 24454 D RestartWorker: Working
03-04 18:00:54.061 23542 24454 D StartService: Starting the Listener
03-04 18:00:54.061 23542 24454 D StartService: Service is started: true
03-04 18:00:54.061 23542 24454 D StartService: nFails: 1
03-04 18:00:54.063 23542 23542 D StartService: onStartCommand
03-04 18:00:54.063 23542 23625 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=other_UUID_1, tags={ org.unifiedpush.distributor.nextpush.services.RestartWorker } ]
03-04 18:00:54.065 23542 23542 D ApiUtils: Found deviceId: UUIDv4
03-04 18:00:54.067 23542 23542 D ApiUtils: cSync done.
03-04 18:01:04.356 23542 21536 D SSEListener: onOpen: 200
03-04 18:01:04.356 23542 21536 D SSEListener: New SSE message event=start message={"type":"start"}
03-04 18:04:04.333 23542 21536 D SSEListener: onFailure
03-04 18:04:04.333 23542 21536 D SSEListener: An error occurred: okhttp3.internal.http2.StreamResetException: stream was reset: INTERNAL_ERROR
03-04 18:04:04.333 23542 21536 D SSEListener: onFailure: 200
03-04 18:04:04.333 23542 21536 D SSEListener: Retrying in 2 s
03-04 18:04:28.614 23542 23626 D RestartWorker: Working
03-04 18:04:28.614 23542 23626 D StartService: Starting the Listener
03-04 18:04:28.614 23542 23626 D StartService: Service is started: true
03-04 18:04:28.614 23542 23626 D StartService: nFails: 1
03-04 18:04:28.616 23542 23625 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=other_UUID_2, tags={ org.unifiedpush.distributor.nextpush.services.RestartWorker } ]
03-04 18:04:28.618 23542 23542 D StartService: onStartCommand
03-04 18:04:28.619 23542 23542 D ApiUtils: Found deviceId: UUIDv4
03-04 18:04:28.620 23542 23542 D ApiUtils: cSync done.
03-04 18:04:29.202 23542 21677 D SSEListener: onOpen: 200
03-04 18:04:29.202 23542 21677 D SSEListener: New SSE message event=start message={"type":"start"}
03-04 18:07:29.133 23542 21677 D SSEListener: onFailure
03-04 18:07:29.133 23542 21677 D SSEListener: An error occurred: okhttp3.internal.http2.StreamResetException: stream was reset: INTERNAL_ERROR
03-04 18:07:29.134 23542 21677 D SSEListener: onFailure: 200
03-04 18:07:29.134 23542 21677 D SSEListener: Retrying in 2 s
03-04 18:08:15.290 23542 24093 D RestartWorker: Working
03-04 18:08:15.291 23542 24093 D StartService: Starting the Listener
03-04 18:08:15.291 23542 24093 D StartService: Service is started: true
03-04 18:08:15.292 23542 24093 D StartService: nFails: 1
03-04 18:08:15.297 23542 23542 D StartService: onStartCommand
03-04 18:08:15.298 23542 23564 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=other_UUID_3, tags={ org.unifiedpush.distributor.nextpush.services.RestartWorker } ]
03-04 18:08:15.300 23542 23542 D ApiUtils: Found deviceId: UUIDv4
03-04 18:08:15.302 23542 23542 D ApiUtils: cSync done.
03-04 18:08:15.999 23542 22027 D SSEListener: onOpen: 200
03-04 18:08:16.000 23542 22027 D SSEListener: New SSE message event=start message={"type":"start"}
03-04 18:08:19.291 23542 23559 D StartService: Network Capabilities changed
03-04 18:08:22.381 23542 23559 D StartService: Network Capabilities changed
03-04 18:11:16.742 23542 22027 D SSEListener: onFailure
03-04 18:11:16.742 23542 22027 D SSEListener: An error occurred: okhttp3.internal.http2.StreamResetException: stream was reset: INTERNAL_ERROR
03-04 18:11:16.742 23542 22027 D SSEListener: onFailure: 200
03-04 18:11:16.742 23542 22027 D SSEListener: Retrying in 2 s
03-04 18:11:24.341 23542 24395 D RestartWorker: Working
03-04 18:11:24.341 23542 24395 D StartService: Starting the Listener
03-04 18:11:24.341 23542 24395 D StartService: Service is started: true
03-04 18:11:24.341 23542 24395 D StartService: nFails: 1
03-04 18:11:24.345 23542 23542 D StartService: onStartCommand
03-04 18:11:24.345 23542 23558 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=other_UUID_4, tags={ org.unifiedpush.distributor.nextpush.services.RestartWorker } ]
03-04 18:11:24.346 23542 23542 D ApiUtils: Found deviceId: UUIDv4
03-04 18:11:24.347 23542 23542 D ApiUtils: cSync done.
03-04 18:11:26.063 23542 22185 D SSEListener: onOpen: 200
03-04 18:11:26.064 23542 22185 D SSEListener: New SSE message event=start message={"type":"start"}

"other_UUID_x" I have numbered this because there were 3 different ids

these are the times of logs at nextcloud

18:11:22
18:08:12
18:04:25
p1gp1g commented 2 years ago

Sorry for the delay to answer.

The logs show that there is still a 3min tiemout on your server. If you can't increase it, you should reduce the timeout setting in the nextcloud app to 150secondes.

Tealk commented 2 years ago

Should no longer be so, the following is in my vhost.

location /index.php/apps/uppush/ {
  fastcgi_buffering off;
  fastcgi_connect_timeout 10m;
  fastcgi_send_timeout 10m;
  fastcgi_read_timeout 10m;
}

The only thing I can imagine is that the location would have to be written differently and therefore the rule does not apply.

p1gp1g commented 2 years ago

Try with location ^~ /index.php/apps/uppush/

Nginx logs may give more information

Tealk commented 2 years ago

Try with location ^~ /index.php/apps/uppush/

Now i get: 2022/03/14 20:33:09 [error] 65971#65971: *43828 open() "WEBPATH/index.php/apps/uppush/device/UUID" failed (20: Not a directory), client: IP, server: rollenspiel.cloud, request: "GET /index.php/apps/uppush/device/UUID HTTP/2.0", host: "rollenspiel.cloud"

with the old setting 2022/03/14 20:25:02 [error] 384#384: *43421 recv() failed (104: Connection reset by peer) while reading upstream, client: IP, server: rollenspiel.cloud, request: "GET /index.php/apps/uppush/device/UUID HTTP/2.0", upstream: "fastcgi://unix:/var/lib/fastcgi/6-anzah-rollenspiel.cloud-php-fpm.socket:", host: "rollenspiel.cloud"

p1gp1g commented 2 years ago

Well, it depends on your setup then. It seems there might be errors with symlinks (https://stackoverflow.com/questions/53617881/nginx-error-openat-failed-20-not-a-directory-for-images)

Tealk commented 2 years ago

Currently, I probably get with the following setting no more error messages:

location ^~ /index.php/apps/uppush/ {
    disable_symlinks off;
    fastcgi_buffering off;
    fastcgi_connect_timeout 10m;
    fastcgi_send_timeout 10m;
    fastcgi_read_timeout 10m;
}