help: fresh install keeps logining out as time out

[jpahullo]

Hi,

I reset my dev environment and I started from scratch using this repo, as before.

I build a Moodle 3.11 fresh install, building the set of containers, installing via CLI the database as suggested. All ok right now.

I log in as admin/test. Ok. I can click everywhere on the empty Moodle.

However, when I click on the Administration menu, it logs me out. And I cannot reenter into Moodle. No way.

I tried it for 3 times to start from scratch, and every time I got the same behaviour.

I can see that every failed attempt to log in, it creates a new session file, with the time stamp internal to the container apache webserver.

The loop for any admin login trial is:

1. "POST /login/index.php HTTP/1.1" 303 2141 "http://localhost/login/index.php"
2. "GET /login/index.php?testsession=2 HTTP/1.1" 303 1955 "http://localhost/login/index.php"
   • admin is user.id = 2. so ok.
3. "GET /admin/search.php HTTP/1.1" 303 2025 "http://localhost/login/index.php"
   • enters into the admin_externalpage_setup()
   • then into the require_login()
   • finally in the lib/moodlelib.php::reguire_login() it detects that the user is not logged in. $USER->id = 0.
4. "GET /login/index.php HTTP/1.1" 303 1954 "http://localhost/login/index.php"
5. "GET /login/index.php HTTP/1.1" 200 8077 "http://localhost/login/index.php"
   • here the message is that my session was timed out.

Incredibly. I cannot understand why I am facing this recurrent problem.

Any ideas? Thanks a lot in advance.

[scara]

Hi @jpahullo, could you share the exact sequence of commands used to run your Moodle 3.11 code, including your docker version and OS? I'd like to replicate it in my own env.

HTH, Matteo

[jpahullo]

Thanks!

I'm at work. This afternoon I'll share the sequence.

Today, comming to work, I was thinking about the UTC timezone. I realized there were 1h of difference between host and container time (1 hour less in the container timezone). Maybe is this the reason of logging me out, since web browser says it is 1h after the session cookie? I'll try this this evening, mounting the local timezone file into the container, to unify timezones.

I'll share all these details.

Thanks @scara for your quick reply!

Best,

Jordi

[jpahullo]

Hi @scara,

Here are my findings.

Firstly I tried what I told you about the timezone. In my local.yml I have:

version: "2"
services:
    webserver:
        volumes:
            - "/etc/timezone:/etc/timezone:ro"
            - "/etc/localtime:/etc/localtime:ro"

Then, started all containers and checked the date:

$ date; docker exec -it moodle311-webserver-1 date
dijous, 23 de març de 2023, 21:14:25 CET
Thu Mar 23 21:14:25 CET 2023

so, they are the same timezone.

Sadly, this does not solve anything. It keeps logging me out (zip includes an animated gif - editor prevented from uploading it directly):

logging-me-out.zip

Answering your first questions:

I have built some scripts to include the whole start up, stop and fresh install scripts, wrapping the project binaries:

$ cd /my/code
$ git clone https://github.com/moodlehq/moodle-docker.git
$ cd moodle-docker
$ mkdir -p 311/web
$ mkdir -p 311/data
$ cd 311/web
$ git clone https://github.com/moodle/moodle.git -b MOODLE_311_STABLE
# Own script to gather all variables, useful for self-documentation:
$ cat moodle-docker.env
export MOODLE_DOCKER_DB=mysql
export MOODLE_DOCKER_DB_PORT=3306
export MOODLE_DOCKER_WEB_PORT=80
export MOODLE_DOCKER_DBPASS="m@0dl3ing"
export MOODLE_DOCKER_DBUSER="moodle"
export MOODLE_DOCKER_PHP_VERSION=7.4
export MOODLE_DOCKER_MOODLE_VERSION=311
export MOODLE_DOCKER_WWWROOT=/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/web/
export COMPOSE_PROJECT_NAME=moodle$MOODLE_DOCKER_MOODLE_VERSION
$ cat ../../start.sh # executable: chmod +x ../../start.sh
#/bin/bash

thisdir=$(realpath $(dirname $0))

if [ -f moodle-docker.env ];
then
  . moodle-docker.env
else
    echo "missing moodle-docker.env file"
    exit 1
fi

if [ ! -f "$MOODLE_DOCKER_WWWROOT/config.php" ];
then
  cp "$thisdir"/config.docker-template.php "$MOODLE_DOCKER_WWWROOT/config.php"
fi

"$thisdir"/bin/moodle-docker-compose up -d
"$thisdir"/bin/moodle-docker-wait-for-db

$ cat ../../destroy.sh # executable: chmod +x ../../destroy.sh
#/bin/bash

thisdir=$(realpath $(dirname $0))

if [ -f moodle-docker.env ];
then
  . moodle-docker.env
else
    echo "missing moodle-docker.env file"
    exit 1
fi

"$thisdir"/bin/moodle-docker-compose down

$ cat ../../install.sh # executable: chmod +x ../../install.sh
#!/bin/bash

thisdir=$(realpath $(dirname $0))

if [ -f moodle-docker.env ];
then
  . moodle-docker.env
else
    echo "missing moodle-docker.env file"
    exit 1
fi

# Initialize Moodle database for manual testing
"$thisdir"/bin/moodle-docker-compose exec webserver \
    php admin/cli/install_database.php \
    --agree-license \
    --fullname="Docker $MOODLE_DOCKER_MOODLE_VERSION moodle" \
    --shortname="docker_${MOODLE_DOCKER_MOODLE_VERSION}_moodle" \
    --summary="Docker $MOODLE_DOCKER_MOODLE_VERSION moodle site" \
    --adminpass="test" \
    --adminemail="admin@example.com"

$ cat ../../local.yml # Custom bindings to ease debugging and accessing to data files; also to keep database from run to run.
version: "2"
services:
    webserver:
        volumes:
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/web:/var/www/html"
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/data/moodledata:/var/www/moodledata"
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/data/phpunitdata:/var/www/phpunitdata"
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/data/behatdata:/var/www/behatdata"
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/data/behatfaildumps:/var/www/behatfaildumps"
            - "/etc/timezone:/etc/timezone:ro"
            - "/etc/localtime:/etc/localtime:ro"
    db:
        volumes:
            - "/my/code/moodle-docker/$MOODLE_DOCKER_MOODLE_VERSION/data/mysqldata:/var/lib/mysql"

# So,  I started the trial site as follows:

$ pwd
/my/code/moodle-docker/311/web
$ . moodle-docker.env # load all environment variables for this site.
$ ../../start.sh # This starts the containers and creates empty db.
$ ../../install.sh # This installs Moodle from CLI, non-interactive.
# Go to http://localhost and it will show you that MOODLEDATA is not writable:
$ sudo chmod -R 777 ../web/
# Visit again http://localhost and it will show you the Moodle site.

On http://localhost with your Moodle Site, try to log in with user admin/test. If you click on any link, it goes ok. The first time you click on "Administration" link, it logs me out and, since then, I can never log in again.

The saddest part is that, years ago, it happened to me also, exactly the same, and I solved it. But I have no notes on how. And now, I cannot see what it the bit that makes it bad.

I'll keep investigating.

Thanks a lot,

Jordi

[jpahullo]

No way yet.

For your information @scara:

I share here how sessions files are generated inside the container:

root@7b4e93f319c6:/var/www/moodledata# ls -lah sessions/
total 40K
drwxrwxrwx 2 www-data www-data 4.0K Mar 24 00:17 .
drwxrwxrwx 9 www-data www-data 4.0K Mar 22 22:31 ..
-rw------- 1 www-data www-data 1.7K Mar 24 00:14 sess_3cd74cdbca9997efe09676f556289e1e
-rw------- 1 www-data www-data 1.3K Mar 24 00:10 sess_5b32e11e6000d4fd1c3b8eaa122c285e
-rw------- 1 www-data www-data  515 Mar 24 00:17 sess_5e184620284a4f42859ea5209ddbe2b0
-rw------- 1 www-data www-data 1.7K Mar 24 00:11 sess_658e28e0991675b18eee706221cf3736
-rw------- 1 www-data www-data 1.7K Mar 24 00:11 sess_908db7fb55adb8769dc0a96cf9218050
-rw------- 1 www-data www-data 4.6K Mar 24 00:10 sess_9d8fba63a39495b822cd913b2d68fcd4
-rw------- 1 www-data www-data 1.7K Mar 24 00:17 sess_a04d2b1863ba8283bf888a9365687d79
root@7b4e93f319c6:/var/www/moodledata# ls -lah ..
total 32K
drwxr-xr-x  1 root     root     4.0K Mar 20 11:27 .
drwxr-xr-x  1 root     root     4.0K Nov 15 05:13 ..
drwxrwxrwx  2 www-data www-data 4.0K Mar 22 22:26 behatdata
drwxrwxrwx  2 www-data www-data 4.0K Mar 22 22:26 behatfaildumps
drwxrwxr-x 61     1000 www-data 4.0K Mar 24 00:24 html
drwxrwxrwx  9 www-data www-data 4.0K Mar 22 22:31 moodledata
drwxrwxrwx  2 www-data www-data 4.0K Mar 22 22:26 phpunitdata
root@7b4e93f319c6:/var/www/moodledata#

Apparently, ownership is ok and file permissions too.

Every time I try to log in, the system generates a new sess_* file.

Running xdebug, step by step in phpstorm, I could see that:

1. login page performs well, and loads the $USER for the admin.
2. login page, then, tries to apply for the testsession=2 (2 is the admin user id)
3. when loads for the second time this login/index.php?testsession=2, here, the system does not loads any user session data and I can see user.id = 0.

I do not know. It'd be easy peasy, but no way.... :-(

I think it should be about permissions and php sessions, but no luck yet.

Any idea/suggestion/whatever, would be very welcome.

Thanks,

Jordi

[jpahullo]

Hi,

I reached to step debug with Xdebug to find the point where it breaks:

https://github.com/moodle/moodle/blob/master/lib/classes/session/manager.php#L420

That $sid = session_id(); is the same from login/index.php and login/index.php?testsession, but it is a different $sid when visiting the admin/search.php (it was recorded as wantsurl). However, all the time is detected as not new, but the $sid differs from login/index.php?testsession to admin/search.php.

Any idea @scara why this is happening?

Thanks,

Jordi

[jpahullo]

I've visited the whole PHP configuration, I installed rsyslog in the container, revisited the php.ini configuration with development configuration.

Nothing particular.

[jpahullo]

Well, I went to my browser, and decided to clear any cookie from the site localhost.

After that, I can successfully navigate into the Administration menu.

Incredible.

I will put a reference of this in the README.md of this project to help anyone else, and to me of the future :-P

That was a really, really weird behaviour.

Thanks @scara

[stronk7]

Great detective work, @jpahullo.

And strange behaviour, I cannot understand why that was happening to you... if it happens for real sessions... the very same should happen for behat runs and other stuff... curious, curious...

[jpahullo]

hehehe... thanks @stronk7!

[stronk7]

I'm closing this, now that #260 has been merged. I'm afraid I've not been able to investigate this, but I think you already did all the usual checks and verifications (server-side).

Ciao :-)