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

Error in nextcloud.log after logout #20490

Closed
Nils160988 opened this issue Apr 14, 2020 · 31 comments · Fixed by #22243
Closed

Error in nextcloud.log after logout #20490

Nils160988 opened this issue Apr 14, 2020 · 31 comments · Fixed by #22243
Assignees
Labels
0. Needs triage Pending check for reproducibility or if it fits our roadmap bug
Milestone

Comments

@Nils160988
Copy link
Contributor

How to use GitHub

  • Please use the 👍 reaction to show that you are affected by the same issue.
  • Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
  • Subscribe to receive notifications on status change and new comments.

Steps to reproduce

  1. Upgrade to 19 Beta 2
  2. Login with a user
  3. Logout with this user

Expected behaviour

No error messages in log

Actual behaviour

The nextcloud log shows an error each time a user logs out. So far, I can see no further effects, but it might be interesting for you to find the cause for this error.

Server configuration

Operating system: Ubuntu 18.04.3

Web server: apache 2.4.29

Database: mariadb 10.1.44

PHP version: 7.2.24

Nextcloud version: 19.0.0.3 (Beta 2)

Updated from an older Nextcloud/ownCloud or fresh install: updated

Where did you install Nextcloud from: nextcloud.com

Signing status:

Signing status
No errors have been found.

List of activated apps:

App list
Enabled:
  - accessibility: 1.5.0
  - activity: 2.12.0
  - announcementcenter: 3.8.0
  - calendar: 2.0.3
  - cloud_federation_api: 1.2.0
  - comments: 1.9.0
  - contacts: 3.2.0
  - contactsinteraction: 1.0.0
  - dav: 1.15.0
  - deck: 0.8.2
  - drawio: 0.9.5
  - federatedfilesharing: 1.9.0
  - federation: 1.9.0
  - files: 1.14.0
  - files_mindmap: 0.0.21
  - files_pdfviewer: 1.8.0
  - files_rightclick: 0.16.0
  - files_sharing: 1.11.0
  - files_trashbin: 1.9.0
  - files_versions: 1.12.0
  - files_videoplayer: 1.8.0
  - firstrunwizard: 2.8.0
  - groupfolders: 6.0.5
  - logreader: 2.4.0
  - lookup_server_connector: 1.7.0
  - nextcloud_announcements: 1.8.0
  - notifications: 2.7.0
  - oauth2: 1.7.0
  - password_policy: 1.9.0
  - photos: 1.1.0
  - privacy: 1.3.0
  - provisioning_api: 1.9.0
  - recommendations: 0.7.0
  - serverinfo: 1.9.0
  - settings: 1.1.0
  - sharebymail: 1.9.0
  - systemtags: 1.9.0
  - tasks: 0.12.1
  - text: 3.0.1
  - theming: 1.10.0
  - twofactor_backupcodes: 1.8.0
  - twofactor_totp: 4.1.3
  - updatenotification: 1.9.0
  - viewer: 1.3.0
  - workflowengine: 2.1.0
Disabled:
  - admin_audit
  - apporder
  - circles
  - documentserver_community
  - encryption
  - event_update_notification
  - external
  - files_automatedtagging
  - files_external
  - group_everyone
  - impersonate
  - onlyoffice
  - polls
  - ransomware_protection
  - spreed
  - support
  - survey_client
  - user_ldap
  - user_usage_report
  - workflow_pdf_converter
  - workflow_script

Nextcloud configuration:

Config report
{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "test.xyz.de"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/test.xyz.de\/nextcloud",
        "htaccess.RewriteBase": "\/",
        "dbtype": "mysql",
        "version": "19.0.0.3",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "mail_smtpmode": "sendmail",
        "mail_smtpauthtype": "LOGIN",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "default_language": "de",
        "default_locale": "de_DE",
        "logtimezone": "Europe\/Berlin",
        "theme": "",
        "loglevel": 2,
        "updater.release.channel": "beta",
        "skeletondirectory": "\/var\/www\/default-files",
        "maintenance": false,
        "mysql.utf8mb4": true,
        "data-fingerprint": "01ab1f439dc59f5b900a4be407aad640",
        "activity_use_cached_mountpoints": "true"
    }
}

Are you using external storage, if yes which one: no

Are you using encryption: no

Are you using an external user-backend, if yes which one: no

Client configuration

Browser: Firefox 75.0

Operating system:

Logs

Web server error log

Web server error log
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:20 +0200] "GET /logout?requesttoken=vEJgmQniP3UEkDYUF9HDKAocjDxE1t9YtyRByfPKudQ%3D%3AhTYW4XGpBydB4n1feKiGf019znYr%2BYki%2BEEZkJ%2F7gbg%3D HTTP/1.1" 303 1959 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:20 +0200] "GET /login?clear=1 HTTP/1.1" 303 879 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:20 +0200] "GET /login?clear=1 HTTP/1.1" 200 4921 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/deck/css/activity.css?v=2ebc9247-8 HTTP/1.1" 200 928 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/files_pdfviewer/css/style.css?v=4fda350b-8 HTTP/1.1" 200 910 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/css/guest.css?v=4f951eb8-8 HTTP/1.1" 200 6243 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/files_sharing/l10n/de.js?v=4f951eb8-8 HTTP/1.1" 200 5993 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/search/js/search.js?v=4f951eb8-8 HTTP/1.1" 200 2700 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/l10n/de.js?v=4f951eb8-8 HTTP/1.1" 200 19128 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/files_sharing/js/dist/main.js?v=4f951eb8-8 HTTP/1.1" 200 1719 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/files_pdfviewer/js/previewplugin.js?v=4f951eb8-8 HTTP/1.1" 200 2931 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/theming/styles?v=8 HTTP/1.1" 200 1840 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/files_videoplayer/js/main.js?v=4f951eb8-8 HTTP/1.1" 200 3392 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/js/files/fileinfo.js?v=4f951eb8-8 HTTP/1.1" 200 1565 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/search/js/searchprovider.js?v=4f951eb8-8 HTTP/1.1" 200 4431 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/js/files/client.js?v=4f951eb8-8 HTTP/1.1" 200 6408 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /js/core/merged-template-prepend.js?v=4f951eb8-8 HTTP/1.1" 200 4297 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/accessibility/js/accessibility?v=0 HTTP/1.1" 200 951 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/js/dist/login.js?v=4f951eb8-8 HTTP/1.1" 200 229195 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /apps/theming/js/theming?v=8 HTTP/1.1" 200 1130 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /core/js/dist/main.js?v=4f951eb8-8 HTTP/1.1" 200 423540 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:21 +0200] "GET /svg/core/logo/logo?color=fff&v=1 HTTP/1.1" 200 1169 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:22 +0200] "GET /core/img/favicon.ico HTTP/1.1" 200 3884 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"
xxx.xxx.xxx.xxx - - [15/Apr/2020:00:18:22 +0200] "GET /core/img/favicon-touch.png HTTP/1.1" 200 3525 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0"

Nextcloud log (data/nextcloud.log)

Nextcloud log
{"reqId":"lKYXO4j9SrEvPvDGVDpJ","level":3,"time":"2020-04-15T00:18:20+02:00","remoteAddr":"xxx.xxx.xxx.xxx","user":"--","app":"PHP","method":"GET","url":"/logout?requesttoken=vEJgmQniP3UEkDYUF9HDKAocjDxE1t9YtyRByfPKudQ%3D%3AhTYW4XGpBydB4n1feKiGf019znYr%2BYki%2BEEZkJ%2F7gbg%3D","message":"session_start(): A session had already been started - ignoring at /var/www/test-nextcloud/lib/private/Session/Internal.php#209","userAgent":"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0","version":"19.0.0.3"}
@Nils160988 Nils160988 added bug 0. Needs triage Pending check for reproducibility or if it fits our roadmap 19-feedback labels Apr 14, 2020
@cgzones
Copy link

cgzones commented Apr 23, 2020

OS: Debian Sid
Apache: 2.4.43-1
PHP: 7.4.5-1

{"reqId":"XqHXTWUb@-TAzm7MZj0EaQAAAAg","level":3,"time":"2020-04-23T17:58:37+00:00","remoteAddr":"replaced_ip","user":"--","app":"PHP","method":"GET","url":"/index.php/logout?requesttoken=replaced_token","message":"session_start(): A session had already been started - ignoring at /var/www/sites/nextcloud/lib/private/Session/Internal.php#209","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0","version":"19.0.0.6"}

@rullzer rullzer self-assigned this May 7, 2020
@MeiRos
Copy link

MeiRos commented May 14, 2020

I have this issue too. I opened a thread about it few days ago. There are more information about my setup etc.
https://help.nextcloud.com/t/a-session-had-already-been-started/81037

@AndyXheli

This comment has been minimized.

@LHollyfeld

This comment has been minimized.

@Ruinenarr

This comment has been minimized.

@tacruc
Copy link
Contributor

tacruc commented Jun 4, 2020

Probably related to: nextcloud/maps#397

@Rob3487

This comment has been minimized.

@ml94

This comment has been minimized.

@returntrip
Copy link

This issue happens for me systematically when refreshing/fetching articles from the Nextcloud News for Android:

[PHP] Error: session_start(): A session had already been started - ignoring at /var/www/html/lib/private/Session/Internal.php#209

PUT /index.php/apps/news/api/v1-2/items/read/multiple?
from 10.0.1.1 at 2020-06-08T11:31:16+00:00

System Information

  • News app version: 14.1.11
  • Nextcloud version: 19 (Docker)

@Rob3487
Copy link

Rob3487 commented Jun 8, 2020

Same issue , fresh instalation , 19.0.0
Ubuntu 20.04
Apache 2.4.41
PHP 7.3.18

In my case the behavior turned out to be a database connection issue.
I no longer experience the error.

@Ruinenarr
Copy link

Same issue , fresh instalation , 19.0.0
Ubuntu 20.04
Apache 2.4.41
PHP 7.3.18

In my case the behavior turned out to be a database connection issue.
I no longer experience the error.

How did you find the issue? Maybe it could solve it at other installation aswell.

@Rob3487
Copy link

Rob3487 commented Jun 10, 2020

I reviewed my stack, re-checking for possiblie issues.

The shortfall for me was that when the nextcloud install process ran, at what point appeard to me to be completion of the install process (1st time install for me), the error displayed was not indicative of the actual problem.
The error reading:

"session_start(): A session had already been started - ignoring at /opt/nextcloud/lib/private/Session/Internal.php#205"

The "nextcloud pre-test for satisfactory resources" (eg.checking for database and php modules) had completed successfully, passing my system as ready for the install.

The nextcloud pre-test for install prerequisits DID correctly identify that I had a suitable database installed (as it had failed previously and I remedied that) , however the nextcloud pre-test did NOT identity that the database php/apache connection was not working, php was not connecting to the database.

The actual problem was that the php/apache database module was not engaing the database (postgresql in my case). In spite of appearing that the nextcloud install had completed resulting with a session() issue, infact the nextcloud install (post-downloading the nextcloud files) must have not even begun, as there was no database connection working at all.

The nextcloud developers and community have done a fantastic job - nextcloud is very impressive! - thanks to all!

PS.
I ended up within this thread as I was lead to this thread from the thread;
"nextcloudcmd fills the logs with "session_start(): A session had already been started - ignoring at /opt/nextcloud/lib/private/Session/Internal.php#205" #17185"

Now that I have identified the source of my issue, perhaps makes sence to move my post here to #17185 .

@d0m1n1q0
Copy link

@Rob3487
No offense. Despite my language command, I can't figure out what you are talking about.
Let alone providing a solution.
Cheers

@LgWagon

This comment has been minimized.

@barzog

This comment has been minimized.

@steadybright

This comment has been minimized.

@HolgerHees
Copy link
Contributor

for me the same happens.

maybe it is an API related problem. It happens for me for the news and the notes native app.

means the web version works fine, but if I start the android apps I get this error.

btw. the native nextcloud app works without any error.

@d0m1n1q0

This comment has been minimized.

@d0m1n1q0
Copy link

That’s because the app does not log-out

@HolgerHees
Copy link
Contributor

HolgerHees commented Jun 17, 2020

what you mean with logout.

normally you call session_start to create a new session or to resume a session based on submitted session id and you do this on every request.

Why should a app log-out for every new request?

or to rephrase, which kind of bug report should I send to the native apps developers of the news and notes app. Is there any documentation about this changed nextcloud behavior I could forward?

@d0m1n1q0
Copy link

Try the following.

Do not logout.
Kill your browser whilst logged-in.
Log-in again
There is no error recorded.

Which is similar to closing the mobile app.

@HolgerHees
Copy link
Contributor

HolgerHees commented Jun 17, 2020

I debugged it a little bit more.

when the error occurs the following happens.

  1. session_start is called like always.
  2. then, in OC\AppFramework\Middleware\Security\CORSMiddleware->beforeController is called
  3. this will call OC\User\Session->logout
  4. OC\Session\CryptoSessionData->clear is called
  5. OC\Session\Internal->clear is called
    5.1. this will call session_unset() which deletes all php session variables
    5.2. then OC\Session\Internal->regenerateId() which calles session_regenerate_id() which will start and regenerate a new session
    5.3 then OC\Session\Internal->sessionStart() is called which will call session_start() again, which should not happen. Because the session is already started.

to summarize.

I think the function OC\Session\Internal->clear has an error, because it is calling session_regenerate_id followed by a session_start. But session_regenerate_id was already starting the session.

HolgerHees added a commit to HolgerHees/server that referenced this issue Jun 18, 2020
This will fix errors like "A session had already been started"

The reason was that there was a already started session and ->regenerateId() was assigning a new session id to it. So there is no need to call start_session() again.

This will fix nextcloud#20490
@solracsf
Copy link
Member

@HolgerHees thanks, can you make a PR about this for reviewing?

@Dellyjoe
Copy link

Hello Everyone,

Why is this still open if a fix has been made. I ended up using @HolgerHees Fix when looking at Internal.php and it seems to be working"?

Is this a temp fix? and the community as a whole are looking into a more permit fix?

Thank you for reading,
Joe

rullzer added a commit that referenced this issue Aug 14, 2020
Fixes #20490

Basically restroring the old behavior.

Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>
@MorrisJobke MorrisJobke added this to the Nextcloud 20 milestone Aug 14, 2020
backportbot-nextcloud bot pushed a commit that referenced this issue Aug 14, 2020
Fixes #20490

Basically restroring the old behavior.

Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>
@solracsf
Copy link
Member

@Dellyjoe #22243 is the right fix.

@frlan
Copy link

frlan commented Aug 21, 2020

Wondering whether the fix made it to 19.0.1 -- as running that version I still can see them.

@korelstar
Copy link
Member

@frlan No, it will be in 19.0.2, see #22247

@yan12125
Copy link
Contributor

The fix #22243 seems not working on PHP 8. See #25807

@debaba
Copy link

debaba commented Jul 23, 2021

Stiil having the same.
Running Nextcloud 21.0.1.1
Latest patch level
Major version still supported
Scanned at 2021-04-15 13:53:18

@osm-frasch
Copy link

I probably have the same problem. However, only in Firefox (currently 121)
After I log out of the Password app, I can no longer access the administration settings, the dashboard and the user account administration. (Internal server error, the server could not complete the request).

I have opened Chrome in parallel and am also logged into Nextcloud there. There I can access all apps and the settings without a server error

(Nextcloud: 27.1.5, PhP: 8.1)

@joshtrichards
Copy link
Member

@osm-frasch Can you open a dedicated issue with your full details? This issue has been closed for several years so it's likely that - even if related - it's an independent issue. That said, if you're getting a internal server error, your nextcloud.log will have further details. You may also wish to post at the Nextcloud Help Forum - https://help.nextcloud.com

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
0. Needs triage Pending check for reproducibility or if it fits our roadmap bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.