PHP-MongoDB AuthenticationAbandoned: Overridden by new authentication session

20 viewsdockermongodbphp
0

I am running Nginx + PHP-FPM + MongoDB using Docker containers.

Here is my docker-compose.yml

version: '3.2'
name: app
services:

  nginx:
    container_name: app-nginx
    build:
      context: ./nginx
      dockerfile: Dockerfile
    ports:
      - 80:80
      - 443:443
    volumes:
      - ../src:/var/www/html:ro
    depends_on:
      - php-fpm

  php-fpm:
    container_name: app-php-fpm
    build:
      context: .
      dockerfile: Dockerfile
    volumes:
      - ../src:/var/www/html
    links:
      - "mysql:mysqldb"
      - "mongo:mongodb"
    environment:
      YII_ENV: 'prod'
      YII_DEBUG: '0'

    depends_on:
      - mysql
      - mongo

  mysql:
    container_name: app-mysql
    image: mysql:8.0
    volumes:
      - mysqldb:/var/lib/mysql
    environment:
      MYSQL_ROOT_PASSWORD: ${MYSQL_ROOT_PASSWORD}
      MYSQL_DATABASE: ${MYSQL_DATABASE}
      MYSQL_USER: ${MYSQL_USER}
      MYSQL_PASSWORD: ${MYSQL_PASSWORD}

  mongo:
    container_name: app-mongo
    image: mongo:7.0
    volumes:
     - mongodb:/data/db
    environment:
      MONGO_INITDB_ROOT_USERNAME: ${MONGO_INITDB_ROOT_USERNAME}
      MONGO_INITDB_ROOT_PASSWORD: ${MONGO_INITDB_ROOT_PASSWORD}

volumes:
  mysqldb:
    name: app-mysql-db
    driver: local
  mongodb:
    name: app-mongo-db
    driver: local

networks:
  default:
    name: app-network

The PHP-FPM Dockerfile:

FROM php:8.3-fpm-alpine

# Use the default production configuration
RUN mv "$PHP_INI_DIR/php.ini-production" "$PHP_INI_DIR/php.ini"

# Install required utilities
RUN apk update 
    && apk add --no-cache icu icu-data-full libzip libpng libjpeg-turbo libwebp freetype

# Install deps, compile php extensions, install extensions, and purge the temp libraries
RUN apk add --no-cache --virtual build-essentials 
        ${PHPIZE_DEPS} curl-dev openssl-dev icu-dev libzip-dev libpng-dev libwebp-dev libjpeg-turbo-dev freetype-dev 
    && pecl install mongodb 
    && docker-php-ext-enable mongodb 
    && docker-php-ext-install zip 
    && docker-php-ext-install pdo_mysql 
    && docker-php-ext-configure intl 
    && docker-php-ext-install intl 
    && docker-php-ext-configure gd --enable-gd --with-freetype --with-jpeg --with-webp 
    && docker-php-ext-install gd 
    && apk del build-essentials 
    && rm -rf /usr/src/php* 
    && rm -rf /tmp/pear

# Install PHP composer
RUN php -r "copy('https://getcomposer.org/installer', 'composer-setup.php');" 
    && php -r "if (hash_file('sha384', 'composer-setup.php') === 'e21205b207c3ff031906575712edab6f13eb0b361f2085f1f1237b7126d785e826a450292b6cfd1d64d92e6563bbde02') { echo 'Installer verified'; } else { echo 'Installer corrupt'; unlink('composer-setup.php'); exit(80); } echo PHP_EOL;"  
    && php composer-setup.php --install-dir=/usr/local/bin --filename=composer 
    && php -r "unlink('composer-setup.php');"

The PHP container runs application on Yii2 framework. There is nothing fancy in the connection setup:

                'statsDb' => [
                        'class' => 'yiimongodbConnection',
                        'dsn' => 'mongodb://'.$credentials['components']['statsDb']['username'].':'.$credentials['components']['statsDb']['password'].'@mongodb:27017/appstats',
                        'options' => [
                                'socketTimeoutMS' => 300000, # 5 minutes
                                'maxIdleTimeMS' => 300000, # 5 minutes
                        ],
                ],

The problem is – approx every minute I get the following errors in MongoDB container logs:

app-mongo  | {"t":{"$date":"2024-01-08T20:15:11.460+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn25","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:37498","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":60175101,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:15:17.066+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn23","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:54348","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":63439603,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:16:02.141+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn24","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:57018","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":64052295,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:16:11.650+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn25","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:37498","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":60190144,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:16:17.070+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn23","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:54348","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":60003787,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:17:08.237+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn24","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:57018","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":66096005,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:17:13.099+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn25","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:37498","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":61448810,"summary":{}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:17:18.822+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn23","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:54348","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Overridden by new authentication session","result":337,"metrics":{"conversation_duration":{"micros":61752258,"summary":{}}},"extraInfo":{}}}

The client IP 172.24.0.4 is PHP-FPM container IP. The strange thing is that connection to the MongoDB works fine, the application is able to read/write data to the Database all the time.

I could not find any resource explaining this particular error: "AuthenticationAbandoned: Overridden by new authentication session"

I tried to set maxIdleTimeMS to 5 minutes to the connection options, but it didn’t change the interval of the errors.

I tried also to make a constant page views to see if the connections remains if web has steady traffic (no idle connections to database).

Also I checked the single connection lifecycle from Mongo logs:

app-mongo  | {"t":{"$date":"2024-01-08T20:27:55.406+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.24.0.4:52552","uuid":{"uuid":{"$uuid":"1f900032-c828-46db-953d-8589d632f586"}},"connectionId":40,"connectionCount":10}}
app-mongo  | {"t":{"$date":"2024-01-08T20:27:55.407+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn40","msg":"client metadata","attr":{"remote":"172.24.0.4:52552","client":"conn40","doc":{"driver":{"name":"mongoc / ext-mongodb:PHP ","version":"1.25.2 / 1.17.2 "},"os":{"type":"Linux","name":"Alpine Linux","version":"3.19.0","architecture":"x86_64"},"platform":"PHP 8.3.1 cfg=0x03d21620c9 posix=200809 stdc=201710 CC=GCC 13.2.1 20231014 CFLAGS="" LDFLAGS="""}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:27:55.407+00:00"},"s":"I",  "c":"ACCESS",   "id":6788604, "ctx":"conn40","msg":"Auth metrics report","attr":{"metric":"acquireUser","micros":0}}
app-mongo  | {"t":{"$date":"2024-01-08T20:27:55.439+00:00"},"s":"I",  "c":"ACCESS",   "id":5286306, "ctx":"conn40","msg":"Successfully authenticated","attr":{"client":"172.24.0.4:52552","isSpeculative":true,"isClusterMember":false,"mechanism":"SCRAM-SHA-256","user":"appuser","db":"appstats","result":0,"metrics":{"conversation_duration":{"micros":32602,"summary":{"0":{"step":1,"step_total":2,"duration_micros":48},"1":{"step":2,"step_total":2,"duration_micros":17}}}},"extraInfo":{}}}
app-mongo  | {"t":{"$date":"2024-01-08T20:27:55.440+00:00"},"s":"I",  "c":"NETWORK",  "id":6788700, "ctx":"conn40","msg":"Received first command on ingress connection since session start or auth handshake","attr":{"elapsedMillis":0}}
app-mongo  | {"t":{"$date":"2024-01-08T20:29:09.051+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn40","msg":"Connection ended","attr":{"remote":"172.24.0.4:52552","uuid":{"uuid":{"$uuid":"1f900032-c828-46db-953d-8589d632f586"}},"connectionId":40,"connectionCount":10}}
app-mongo  | {"t":{"$date":"2024-01-08T20:29:09.052+00:00"},"s":"I",  "c":"ACCESS",   "id":5286307, "ctx":"conn40","msg":"Failed to authenticate","attr":{"client":"172.24.0.4:52552","isSpeculative":false,"isClusterMember":false,"mechanism":"","user":"","db":"","error":"AuthenticationAbandoned: Authentication session abandoned, client has likely disconnected","result":337,"metrics":{"conversation_duration":{"micros":13119620,"summary":{}}},"extraInfo":{}}}