Subscribers/consumers silently disconnect from the queue leaving the app in an infinite loop #1120

FlaviuRadulescu · 2023-10-04T16:09:30Z

FlaviuRadulescu
Oct 4, 2023

Version(s) affected: x.y.z

Description
The subscribers silently disconnect from the queue without throwing any error or giving any message. Is just remaining in the wait method. I am running the scripts in a docker container, which is running in a virtual machine.

How to reproduce

   ini_set('display_errors', 1);
    ini_set('display_startup_errors', 1);
    error_reporting(E_ALL);
    require_once __DIR__ . '/vendor/autoload.php';

    use PhpAmqpLib\Connection\AMQPSSLConnection;

    $sslOptions = array( #https://www.php.net/manual/en/context.ssl.php
                         'disable_compression' => true,
                         'verify_peer'         => false,
                         'allow_self_signed'   => false
    );
    $connection = new AMQPSSLConnection('server, 5671, 'user', 'password', "vhost", $sslOptions);
    $channel = $connection->channel();
    $channel->queue_declare('hello', false, false, false, false);
    echo " [*] Waiting for messages. To exit press CTRL+C\n";
    $callback = function ($msg) {

        echo ' [x] Received ', $msg->body, "\n";
    };
    $channel->basic_consume('hello', '', false, true, false, false, $callback);
    while ($channel->is_open()) {
        $channel->wait();
    }
    $channel->close();
    $connection->close();

Possible Solution
I have been struggling for months. My solution is to restart the physical server every 30 minutes

Additional context

General info

phpinfo()
PHP Version => 8.0.30

System => Linux sd15.cl00.dc00.inf.<redacted>.xyz 5.15.0-76-generic #83-Ubuntu SMP Thu Jun 15 19:16:32 UTC 2023 x86_64
Build Date => Aug  3 2023 17:13:08
Build System => Red Hat Enterprise Linux release 9.2 (Plow)
Build Provider => Remi's RPM repository <https://rpms.remirepo.net/> #StandWithUkraine
Compiler => gcc (GCC) 11.3.1 20221121 (Red Hat 11.3.1-4)
Architecture => x86_64
Server API => Command Line Interface
Virtual Directory Support => disabled
Configuration File (php.ini) Path => /etc
Loaded Configuration File => /etc/php.ini
Scan this dir for additional .ini files => /etc/php.d
Additional .ini files parsed => /etc/php.d/20-bz2.ini,
/etc/php.d/20-calendar.ini,
/etc/php.d/20-ctype.ini,
/etc/php.d/20-curl.ini,
/etc/php.d/20-exif.ini,
/etc/php.d/20-fileinfo.ini,
/etc/php.d/20-ftp.ini,
/etc/php.d/20-gd.ini,
/etc/php.d/20-gettext.ini,
/etc/php.d/20-iconv.ini,
/etc/php.d/20-mbstring.ini,
/etc/php.d/20-phar.ini,
/etc/php.d/20-posix.ini,
/etc/php.d/20-shmop.ini,
/etc/php.d/20-sockets.ini,
/etc/php.d/20-sysvmsg.ini,
/etc/php.d/20-sysvsem.ini,
/etc/php.d/20-sysvshm.ini,
/etc/php.d/20-tokenizer.ini

PHP API => 20200930
PHP Extension => 20200930
Zend Extension => 420200930
Zend Extension Build => API420200930,NTS
PHP Extension Build => API20200930,NTS
Debug Build => no
Thread Safety => disabled
Zend Signal Handling => enabled
Zend Memory Manager => enabled
Zend Multibyte Support => provided by mbstring
IPv6 Support => enabled
DTrace Support => available, disabled

Registered PHP Streams => https, ftps, compress.zlib, php, file, glob, data, http, ftp, compress.bzip2, phar
Registered Stream Socket Transports => tcp, udp, unix, udg, ssl, tls, tlsv1.0, tlsv1.1, tlsv1.2, tlsv1.3
Registered Stream Filters => zlib.*, string.rot13, string.toupper, string.tolower, convert.*, consumed, dechunk, bzip2.*, convert.iconv.*

This program makes use of the Zend Scripting Language Engine:
Zend Engine v4.0.30, Copyright (c) Zend Technologies

# Extensions
Array
(
    [9] => pcntl
    [19] => mbstring
    [29] => sockets
)

PHP_INT_SIZE=8
PHP_INT_MAX=9223372036854775807
# Constants
AF_INET                       2
AF_INET6                      10
AF_UNIX                       1
AI_ADDRCONFIG                 32
AI_ALL                        16
AI_CANONIDN                   128
AI_CANONNAME                  2
AI_IDN                        64
AI_NUMERICHOST                4
AI_NUMERICSERV                1024
AI_PASSIVE                    1
AI_V4MAPPED                   8
IPPROTO_IP                    0
IPPROTO_IPV6                  41
IPV6_HOPLIMIT                 52
IPV6_MULTICAST_HOPS           18
IPV6_MULTICAST_IF             17
IPV6_MULTICAST_LOOP           19
IPV6_PKTINFO                  50
IPV6_RECVHOPLIMIT             51
IPV6_RECVPKTINFO              49
IPV6_RECVTCLASS               66
IPV6_TCLASS                   67
IPV6_UNICAST_HOPS             16
IPV6_V6ONLY                   26
IP_MULTICAST_IF               32
IP_MULTICAST_LOOP             34
IP_MULTICAST_TTL              33
MCAST_BLOCK_SOURCE            43
MCAST_JOIN_GROUP              42
MCAST_JOIN_SOURCE_GROUP       46
MCAST_LEAVE_GROUP             45
MCAST_LEAVE_SOURCE_GROUP      47
MCAST_UNBLOCK_SOURCE          44
MSG_CMSG_CLOEXEC              1073741824
MSG_CONFIRM                   2048
MSG_CTRUNC                    8
MSG_DONTROUTE                 4
MSG_DONTWAIT                  64
MSG_EOF                       512
MSG_EOR                       128
MSG_ERRQUEUE                  8192
MSG_MORE                      32768
MSG_NOSIGNAL                  16384
MSG_OOB                       1
MSG_PEEK                      2
MSG_TRUNC                     32
MSG_WAITALL                   256
MSG_WAITFORONE                65536
PHP_BINARY_READ               2
PHP_NORMAL_READ               1
SCM_CREDENTIALS               2
SCM_RIGHTS                    1
SOCKET_E2BIG                  7
SOCKET_EACCES                 13
SOCKET_EADDRINUSE             98
SOCKET_EADDRNOTAVAIL          99
SOCKET_EADV                   68
SOCKET_EAFNOSUPPORT           97
SOCKET_EAGAIN                 11
SOCKET_EALREADY               114
SOCKET_EBADE                  52
SOCKET_EBADF                  9
SOCKET_EBADFD                 77
SOCKET_EBADMSG                74
SOCKET_EBADR                  53
SOCKET_EBADRQC                56
SOCKET_EBADSLT                57
SOCKET_EBUSY                  16
SOCKET_ECHRNG                 44
SOCKET_ECOMM                  70
SOCKET_ECONNABORTED           103
SOCKET_ECONNREFUSED           111
SOCKET_ECONNRESET             104
SOCKET_EDESTADDRREQ           89
SOCKET_EDQUOT                 122
SOCKET_EEXIST                 17
SOCKET_EFAULT                 14
SOCKET_EHOSTDOWN              112
SOCKET_EHOSTUNREACH           113
SOCKET_EIDRM                  43
SOCKET_EINPROGRESS            115
SOCKET_EINTR                  4
SOCKET_EINVAL                 22
SOCKET_EIO                    5
SOCKET_EISCONN                106
SOCKET_EISDIR                 21
SOCKET_EISNAM                 120
SOCKET_EL2HLT                 51
SOCKET_EL2NSYNC               45
SOCKET_EL3HLT                 46
SOCKET_EL3RST                 47
SOCKET_ELNRNG                 48
SOCKET_ELOOP                  40
SOCKET_EMEDIUMTYPE            124
SOCKET_EMFILE                 24
SOCKET_EMLINK                 31
SOCKET_EMSGSIZE               90
SOCKET_EMULTIHOP              72
SOCKET_ENAMETOOLONG           36
SOCKET_ENETDOWN               100
SOCKET_ENETRESET              102
SOCKET_ENETUNREACH            101
SOCKET_ENFILE                 23
SOCKET_ENOANO                 55
SOCKET_ENOBUFS                105
SOCKET_ENOCSI                 50
SOCKET_ENODATA                61
SOCKET_ENODEV                 19
SOCKET_ENOENT                 2
SOCKET_ENOLCK                 37
SOCKET_ENOLINK                67
SOCKET_ENOMEDIUM              123
SOCKET_ENOMEM                 12
SOCKET_ENOMSG                 42
SOCKET_ENONET                 64
SOCKET_ENOPROTOOPT            92
SOCKET_ENOSPC                 28
SOCKET_ENOSR                  63
SOCKET_ENOSTR                 60
SOCKET_ENOSYS                 38
SOCKET_ENOTBLK                15
SOCKET_ENOTCONN               107
SOCKET_ENOTDIR                20
SOCKET_ENOTEMPTY              39
SOCKET_ENOTSOCK               88
SOCKET_ENOTTY                 25
SOCKET_ENOTUNIQ               76
SOCKET_ENXIO                  6
SOCKET_EOPNOTSUPP             95
SOCKET_EPERM                  1
SOCKET_EPFNOSUPPORT           96
SOCKET_EPIPE                  32
SOCKET_EPROTO                 71
SOCKET_EPROTONOSUPPORT        93
SOCKET_EPROTOTYPE             91
SOCKET_EREMCHG                78
SOCKET_EREMOTE                66
SOCKET_EREMOTEIO              121
SOCKET_ERESTART               85
SOCKET_EROFS                  30
SOCKET_ESHUTDOWN              108
SOCKET_ESOCKTNOSUPPORT        94
SOCKET_ESPIPE                 29
SOCKET_ESRMNT                 69
SOCKET_ESTRPIPE               86
SOCKET_ETIME                  62
SOCKET_ETIMEDOUT              110
SOCKET_ETOOMANYREFS           109
SOCKET_EUNATCH                49
SOCKET_EUSERS                 87
SOCKET_EWOULDBLOCK            11
SOCKET_EXDEV                  18
SOCKET_EXFULL                 54
SOCK_DGRAM                    2
SOCK_RAW                      3
SOCK_RDM                      4
SOCK_SEQPACKET                5
SOCK_STREAM                   1
SOL_SOCKET                    1
SOL_TCP                       6
SOL_UDP                       17
SOMAXCONN                     4096
SO_BINDTODEVICE               25
SO_BROADCAST                  6
SO_DEBUG                      1
SO_DONTROUTE                  5
SO_ERROR                      4
SO_KEEPALIVE                  9
SO_LINGER                     13
SO_OOBINLINE                  10
SO_PASSCRED                   16
SO_RCVBUF                     8
SO_RCVLOWAT                   18
SO_RCVTIMEO                   20
SO_REUSEADDR                  2
SO_REUSEPORT                  15
SO_SNDBUF                     7
SO_SNDLOWAT                   19
SO_SNDTIMEO                   21
SO_TYPE                       3
TCP_NODELAY                   1

There are two types of errros in the below logs (ssl and TCP connection)

2023-10-04 13:16:49.027944+00:00 [debug] <0.27731.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:16:49.082764+00:00 [debug] <0.27437.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:16:54.029563+00:00 [debug] <0.27509.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:16:54.082488+00:00 [debug] <0.27508.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:16:59.044601+00:00 [debug] <0.27515.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:16:59.098742+00:00 [debug] <0.27514.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:04.132947+00:00 [debug] <0.27791.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:04.188200+00:00 [debug] <0.27792.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:09.028087+00:00 [debug] <0.27506.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:09.081127+00:00 [debug] <0.27811.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:14.027165+00:00 [debug] <0.27825.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:14.079929+00:00 [debug] <0.27826.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:19.028057+00:00 [debug] <0.27458.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:19.081098+00:00 [debug] <0.27457.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:23.866508+00:00 [warning] <0.25115.63> closing AMQP connection <0.25115.63> (24.77.204.67:41834 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:23.866508+00:00 [warning] <0.25115.63> client unexpectedly closed TCP connection
2023-10-04 13:17:23.866556+00:00 [warning] <0.19151.63> closing AMQP connection <0.19151.63> (24.77.204.67:41848 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:23.866556+00:00 [warning] <0.19151.63> client unexpectedly closed TCP connection
2023-10-04 13:17:23.866875+00:00 [debug] <0.27496.63> Closing all channels from connection '24.77.204.67:41834 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:23.866875+00:00 [debug] <0.27497.63> Closing all channels from connection '24.77.204.67:41848 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:23.867323+00:00 [debug] <0.19996.63> Deleting auto-delete queue 'tasks-x-sd15.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:17:24.025700+00:00 [debug] <0.24456.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:24.078591+00:00 [debug] <0.27862.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:17:24.303533+00:00 [warning] <0.15340.63> closing AMQP connection <0.15340.63> (216.234.102.170:2906 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.303533+00:00 [warning] <0.15340.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.303846+00:00 [debug] <0.24465.63> Closing all channels from connection '216.234.102.170:2906 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:24.312814+00:00 [warning] <0.23724.63> closing AMQP connection <0.23724.63> (216.234.102.170:18751 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.312814+00:00 [warning] <0.23724.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.313104+00:00 [warning] <0.14077.63> closing AMQP connection <0.14077.63> (216.234.102.170:3948 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.313104+00:00 [warning] <0.14077.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.313155+00:00 [debug] <0.24460.63> Closing all channels from connection '216.234.102.170:18751 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:24.313372+00:00 [debug] <0.24455.63> Closing all channels from connection '216.234.102.170:3948 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:24.313601+00:00 [debug] <0.19515.63> Deleting auto-delete queue 'tasks-x-sd17.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:17:24.789162+00:00 [warning] <0.25088.63> closing AMQP connection <0.25088.63> (104.129.216.93:5749 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.789162+00:00 [warning] <0.25088.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.789440+00:00 [warning] <0.19562.63> closing AMQP connection <0.19562.63> (104.129.216.93:4421 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.789440+00:00 [warning] <0.19562.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.789548+00:00 [debug] <0.27867.63> Closing all channels from connection '104.129.216.93:5749 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:17:24.789594+00:00 [warning] <0.15272.63> closing AMQP connection <0.15272.63> (104.129.216.93:10952 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:17:24.789594+00:00 [warning] <0.15272.63> client unexpectedly closed TCP connection
2023-10-04 13:17:24.789731+00:00 [debug] <0.24487.63> Closing all channels from connection '104.129.216.93:4421 -> 135.181.19.245:5671' because it has been closed
--
2023-10-04 13:43:50.155406+00:00 [debug] <0.30609.63> Deleting auto-delete queue 'tasks-x-sd38.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:43:50.331545+00:00 [notice] <0.31930.63> TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC
2023-10-04 13:43:50.331545+00:00 [notice] <0.31930.63>  - decryption_failed
2023-10-04 13:43:50.331771+00:00 [error] <0.31928.63> closing AMQP connection <0.31928.63> (24.77.204.67:46412 -> 135.181.19.245:5671):
2023-10-04 13:43:50.331771+00:00 [error] <0.31928.63> {inet_error,
2023-10-04 13:43:50.331771+00:00 [error] <0.31928.63>     {tls_alert,
2023-10-04 13:43:50.331771+00:00 [error] <0.31928.63>         {bad_record_mac,
2023-10-04 13:43:50.331771+00:00 [error] <0.31928.63>             "TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC\n decryption_failed"}}}
2023-10-04 13:43:50.332072+00:00 [debug] <0.28751.63> Closing all channels from connection '24.77.204.67:46412 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:43:51.113642+00:00 [debug] <0.28744.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:43:51.172220+00:00 [debug] <0.28743.63> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:43:51.259933+00:00 [info] <0.1284.64> accepting AMQP connection <0.1284.64> (24.77.204.67:52822 -> 135.181.19.245:5671)
2023-10-04 13:43:51.271894+00:00 [notice] <0.28005.63> TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC
2023-10-04 13:43:51.271894+00:00 [notice] <0.28005.63>  - decryption_failed
2023-10-04 13:43:51.272133+00:00 [error] <0.23893.63> closing AMQP connection <0.23893.63> (24.77.204.67:40396 -> 135.181.19.245:5671):
2023-10-04 13:43:51.272133+00:00 [error] <0.23893.63> {inet_error,
2023-10-04 13:43:51.272133+00:00 [error] <0.23893.63>     {tls_alert,
2023-10-04 13:43:51.272133+00:00 [error] <0.23893.63>         {bad_record_mac,
2023-10-04 13:43:51.272133+00:00 [error] <0.23893.63>             "TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC\n decryption_failed"}}}
2023-10-04 13:43:51.272538+00:00 [debug] <0.28738.63> Closing all channels from connection '24.77.204.67:40396 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:43:51.272581+00:00 [debug] <0.28098.63> Deleting auto-delete queue 'tasks-x-sd15.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:43:51.404672+00:00 [debug] <0.1284.64> Raw client connection hostname during authN phase: {0,0,0,0,0,65535,34741,
2023-10-04 13:43:51.404672+00:00 [debug] <0.1284.64>                                                     5109}
2023-10-04 13:43:51.404772+00:00 [debug] <0.1284.64> Resolved client hostname during authN phase: ::ffff:135.181.19.245
2023-10-04 13:43:51.404846+00:00 [debug] <0.1284.64> User '<redacted>' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:43:51.568608+00:00 [info] <0.1284.64> connection <0.1284.64> (24.77.204.67:52822 -> 135.181.19.245:5671): user '<redacted>' authenticated and granted access to vhost '<redacted>'
2023-10-04 13:43:51.826392+00:00 [info] <0.1308.64> accepting AMQP connection <0.1308.64> (24.77.204.67:35196 -> 135.181.19.245:5671)
2023-10-04 13:43:51.994512+00:00 [debug] <0.1308.64> Raw client connection hostname during authN phase: {0,0,0,0,0,65535,34741,
2023-10-04 13:43:51.994512+00:00 [debug] <0.1308.64>                                                     5109}
2023-10-04 13:43:51.994619+00:00 [debug] <0.1308.64> Resolved client hostname during authN phase: ::ffff:135.181.19.245
2023-10-04 13:43:51.994694+00:00 [debug] <0.1308.64> User '<redacted>' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:43:52.158704+00:00 [info] <0.1308.64> connection <0.1308.64> (24.77.204.67:35196 -> 135.181.19.245:5671): user '<redacted>' authenticated and granted access to vhost '<redacted>'
2023-10-04 13:43:52.249648+00:00 [info] <0.1372.64> accepting AMQP connection <0.1372.64> (24.77.204.67:52828 -> 135.181.19.245:5671)
2023-10-04 13:43:52.277074+00:00 [notice] <0.27735.63> TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC
2023-10-04 13:43:52.277074+00:00 [notice] <0.27735.63>  - decryption_failed
2023-10-04 13:43:52.277290+00:00 [error] <0.30924.63> closing AMQP connection <0.30924.63> (24.77.204.67:44010 -> 135.181.19.245:5671):
2023-10-04 13:43:52.277290+00:00 [error] <0.30924.63> {inet_error,
2023-10-04 13:43:52.277290+00:00 [error] <0.30924.63>     {tls_alert,
2023-10-04 13:43:52.277290+00:00 [error] <0.30924.63>         {bad_record_mac,
2023-10-04 13:43:52.277290+00:00 [error] <0.30924.63>             "TLS server: In state connection at ssl_record.erl:451 generated SERVER ALERT: Fatal - Bad Record MAC\n decryption_failed"}}}
2023-10-04 13:43:52.277614+00:00 [debug] <0.1411.64> Closing all channels from connection '24.77.204.67:44010 -> 135.181.19.245:5671' because it has been closed
--
2023-10-04 13:54:06.114213+00:00 [debug] <0.1616.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:06.173235+00:00 [debug] <0.1612.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:11.111750+00:00 [debug] <0.1661.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:11.169361+00:00 [debug] <0.1664.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:16.114449+00:00 [debug] <0.1671.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:16.170379+00:00 [debug] <0.1669.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:21.116288+00:00 [debug] <0.1666.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:21.177623+00:00 [debug] <0.2375.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:26.115345+00:00 [debug] <0.2378.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:26.174937+00:00 [debug] <0.2379.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:31.116121+00:00 [debug] <0.2413.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:31.175662+00:00 [debug] <0.2412.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:41.113322+00:00 [debug] <0.2416.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:41.171320+00:00 [debug] <0.1631.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:54:42.690176+00:00 [warning] <0.31306.63> closing AMQP connection <0.31306.63> (195.76.179.94:43892 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:54:42.690176+00:00 [warning] <0.31306.63> client unexpectedly closed TCP connection
2023-10-04 13:54:42.690547+00:00 [debug] <0.2418.64> Closing all channels from connection '195.76.179.94:43892 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:54:46.189979+00:00 [warning] <0.29898.63> closing AMQP connection <0.29898.63> (24.77.204.67:59530 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:54:46.189979+00:00 [warning] <0.29898.63> client unexpectedly closed TCP connection
2023-10-04 13:54:46.190296+00:00 [debug] <0.1642.64> Closing all channels from connection '24.77.204.67:59530 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:54:46.190342+00:00 [debug] <0.1508.64> Deleting auto-delete queue 'tasks-x-sd15.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:54:46.652522+00:00 [warning] <0.28147.63> closing AMQP connection <0.28147.63> (24.77.204.67:37860 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:54:46.652522+00:00 [warning] <0.28147.63> client unexpectedly closed TCP connection
2023-10-04 13:54:46.652836+00:00 [debug] <0.1630.64> Closing all channels from connection '24.77.204.67:37860 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:55:23.334391+00:00 [warning] <0.1444.64> closing AMQP connection <0.1444.64> (24.77.204.67:59528 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:55:23.334391+00:00 [warning] <0.1444.64> client unexpectedly closed TCP connection
2023-10-04 13:55:23.334696+00:00 [debug] <0.2423.64> Closing all channels from connection '24.77.204.67:59528 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:55:41.119525+00:00 [debug] <0.1706.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:55:41.181677+00:00 [debug] <0.1705.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:55:46.663881+00:00 [warning] <0.477.64> closing AMQP connection <0.477.64> (195.76.179.94:42318 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:55:46.663881+00:00 [warning] <0.477.64> client unexpectedly closed TCP connection
2023-10-04 13:55:46.664253+00:00 [debug] <0.1703.64> Closing all channels from connection '195.76.179.94:42318 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:55:46.664355+00:00 [debug] <0.627.64> Deleting auto-delete queue 'tasks-x-sd10.cl00.dc00.inf.<redacted>.xyz' in vhost '<redacted>' because all of its consumers (1) were on a channel that was closed
2023-10-04 13:56:09.584517+00:00 [warning] <0.29333.63> closing AMQP connection <0.29333.63> (195.76.179.94:39250 -> 135.181.19.245:5671, vhost: '<redacted>', user: '<redacted>'):
2023-10-04 13:56:09.584517+00:00 [warning] <0.29333.63> client unexpectedly closed TCP connection
2023-10-04 13:56:09.584842+00:00 [debug] <0.578.64> Closing all channels from connection '195.76.179.94:39250 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:56:41.116709+00:00 [debug] <0.584.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal
2023-10-04 13:56:41.177187+00:00 [error] <0.26055.63> closing AMQP connection <0.26055.63> (195.76.179.94:33036 -> 135.181.19.245:5671):
2023-10-04 13:56:41.177187+00:00 [error] <0.26055.63> missed heartbeats from client, timeout: 60s
2023-10-04 13:56:41.177781+00:00 [debug] <0.654.64> Closing all channels from connection '195.76.179.94:33036 -> 135.181.19.245:5671' because it has been closed
2023-10-04 13:56:41.177863+00:00 [debug] <0.2434.64> User 'Administrator' authenticated successfully by backend rabbit_auth_backend_internal

lukebakken · 2023-10-04T16:20:59Z

lukebakken
Oct 4, 2023
Maintainer

Hello, thanks for using this library and for the issue report.

Please note that I used GitHub Markdown's <details> and <summary> tags to make your issue readable. Another, better, option is to save output to files and attach the files to your issue.

It would be helpful to know the version of this software in your environment:

php-amqplib
RabbitMQ
Erlang

It would also be helpful to know WHEN your client is disconnected so it can be found in the RabbitMQ log file. These are the log lines that probably correspond to your client being disconnected:

2023-10-04 13:56:41.177187+00:00 [error] <0.26055.63> closing AMQP connection <0.26055.63> (195.76.179.94:33036 -> 135.181.19.245:5671):
2023-10-04 13:56:41.177187+00:00 [error] <0.26055.63> missed heartbeats from client, timeout: 60s

This is due to how your code is calling wait(). I'm busy this morning but I will return to this issue to provide assistance.

14 replies

FlaviuRadulescu Oct 6, 2023
Author

is there a way in which I can privately share with you these logs?

if I activate the heartbeat, seems that the consumers are staying connected to the queue (which is great), but when I try to acknowledge or send a message throws a missing heartbeat error and somehow I lose that message. There is constant traffic in the queue, so I don't think we have a problem with disconnection because of too much idle time

Here I think is a disconnect happening


received server heartbeat
> 60,60: Basic.deliver
waiting for a new frame
waiting for a new frame
< 60,80:: Basic.ack
< [hex]: 
0000  01 00 01 00 00 00 0D 00  3C 00 50 00 00 00 00 00   ........ <.P.....
0010  00 00 04 00 CE                                     ....?

< 60,80:: Basic.ack
waiting for any method
waiting for a new frame
closing input
closing socket
< [hex]: 
0000  41 4D 51 50 00 00 09 01                            AMQP.... 

waiting for 10,10
waiting for a new frame
> 10,10: Connection.start
Start from server, version: 0.9, properties: capabilities=(publisher_confirms=1, exchange_exchange_bindings=1, basic.nack=1, consumer_cancel_notify=1, connection.blocked=1, consumer_priorities=1, authentication_failure_close=1, per_consumer_qos=1, direct_reply_to=1), cluster_name=<redacted>, copyright=Copyright (c) 2007-2023 VMware, Inc. or its affiliates., information=Licensed under the MPL 2.0. Website: https://rabbitmq.com, platform=Erlang/OTP 25.0.3, product=RabbitMQ, version=3.11.7, mechanisms: PLAIN, AMQPLAIN, locales: en_US
< 10,11:: Connection.start_ok
< [hex]:

ramunasd Oct 7, 2023
Maintainer

From logs it is visible that connection was closed from client side, either intentionaly or after connection issue. If You did not get exception, it means your consumer closed connection and library works fine.

I tried to reproduce issue with example script, but it did not fail.

Without any additional info I cannot help. We need to have reliable way how to reproduce it.

FlaviuRadulescu Oct 8, 2023
Author

Could we schedule a call so I can show you on a real server how is behaving? I am willing to pay you for your time.

ramunasd Oct 8, 2023
Maintainer

@lukebakken Maybe someone from Your company provides professional support?

lukebakken Oct 8, 2023
Maintainer

Yes, that would be me, actually.

@FlaviuRadulescu I will get caught up on this issue tomorrow.

lukebakken · 2023-10-09T14:00:46Z

lukebakken
Oct 9, 2023
Maintainer

Hi @FlaviuRadulescu

I have re-read this discussion. I can't offer to provide in-person assistance unless someone has a RabbitMQ support contract with VMware (since that's my job).

In order for me to continue assisting you, I need to have the following:

Your code that deals with RabbitMQ. I know you have already done this once but we haven't seen your changes after what @ramunasd pointed out.
Logs from RabbitMQ during the time of these disconnections.
Full AMQP_DEBUG-level output from your application. Save it to a file, and attach the file to your response. When you do a test run we need to know the date, time and timezone of the following so we can correlate them with the RabbitMQ logs:
- Test start
- When the disconnect happened
- Test stop
A description of your infrastructure. We don't know anything about how RabbitMQ is running, or the network between your application and RabbitMQ.

php-amqplib is extremely popular so if this issue were due to a bug in the library, @ramunasd and I would hear about it. There must be something specific to your environment.

Here is a document I put together a while ago that outlines best practices for reporting RabbitMQ issues - https://github.com/rabbitmq/support-tools/blob/main/docs/Reporting_RabbitMQ_Issues.md

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Subscribers/consumers silently disconnect from the queue leaving the app in an infinite loop #1120

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 14 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

Select a reply

Subscribers/consumers silently disconnect from the queue leaving the app in an infinite loop #1120

FlaviuRadulescu Oct 4, 2023

Replies: 2 comments · 14 replies

lukebakken Oct 4, 2023 Maintainer

FlaviuRadulescu Oct 6, 2023 Author

ramunasd Oct 7, 2023 Maintainer

FlaviuRadulescu Oct 8, 2023 Author

ramunasd Oct 8, 2023 Maintainer

lukebakken Oct 8, 2023 Maintainer

lukebakken Oct 9, 2023 Maintainer

FlaviuRadulescu
Oct 4, 2023

Replies: 2 comments 14 replies

lukebakken
Oct 4, 2023
Maintainer

FlaviuRadulescu Oct 6, 2023
Author

ramunasd Oct 7, 2023
Maintainer

FlaviuRadulescu Oct 8, 2023
Author

ramunasd Oct 8, 2023
Maintainer

lukebakken Oct 8, 2023
Maintainer

lukebakken
Oct 9, 2023
Maintainer