Could not connect to DC 1 in MadelineProto/DataCenter.php:300

[shawn-digitalpoint]

Have been running into this a few times a week. It just happened again with a simple method call (getSelf) and the whole thing came crashing down with the exception.

I've set the process up to restart automatically and it instantly works when the process restarts, but it seems like it shouldn't need to be restarted like that.

Restarting of the MadelineProto process and the same function/method works as expected.

Mar 22 11:01:36 host1 WebSocketServer.php[11995]: MadelineProto[0]: getSelf
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: \danog\MadelineProto\Exception: Could not connect to DC 1 in /home/sites/test/web/src/addons/Messaging/vendor/danog/madelineproto/src/danog/MadelineProto/DataCenter.php:300
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: TL Trace:
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Connection.php(607): dcConnect("1",0)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: reconnect()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Coroutine.php(170): throw({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Coroutine.php(112): throw({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Failure.php(30): danog\MadelineProto{closure}({},null)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Placeholder.php(123): onResolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Placeholder.php(153): resolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Coroutine.php(110): fail({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Placeholder.php(40): Amp{closure}(null,null)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: PrivatePromise.php(26): onResolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Placeholder.php(123): onResolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Deferred.php(52): resolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: functions.php(257): resolve({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Placeholder.php(128): Amp\Promise{closure}(null,null)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Deferred.php(52): resolve(null)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: DnsConnector.php(71): resolve()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: NativeDriver.php(302): Amp\Socket{closure}()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: NativeDriver.php(100): selectStreams()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Driver.php(117): dispatch(true)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Driver.php(61): tick()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Loop.php(90): run()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: Tools.php(293): run({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: entry.php(99): wait({})
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got final message from worker: entry.php(122): {closure}()Got exception in IPC server, exiting...
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got final message from worker:
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Process worker exited with 0!
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: Exception: Process worker exited with 0! in ProcessRunner.php:59
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ClientAbstract: Got exception while receiving in IPC client: Amp\ByteStream\ClosedException: The stream was closed by the peer in /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/byte-stream/lib/ResourceOutputStream.php:166
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: Stack trace:
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #0 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/byte-stream/lib/ResourceOutputStream.php(130): Amp\ByteStream\ResourceOutputStream->send('\x00(\x00\x00\x00O:28:"Amp\...', false)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #1 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.danog/ipc/lib/Sync/ChannelledStream.php(45): Amp\ByteStream\ResourceOutputStream->write('\x00(\x00\x00\x00O:28:"Amp\...')
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #2 [internal function]: Amp\Ipc\Sync\ChannelledStream->Amp\Ipc\Sync{closure}()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #3 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Coroutine.php(52): Generator->current()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #4 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/functions.php(91): Amp\Coroutine->__construct(Object(Generator))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #5 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.danog/ipc/lib/Sync/ChannelledStream.php(49): Amp\call(Object(Closure))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #6 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.danog/ipc/lib/Sync/ChannelledSocket.php(54): Amp\Ipc\Sync\ChannelledStream->send(Object(Amp\Ipc\Sync\ChannelCloseAck))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #7 [internal function]: Amp\Ipc\Sync\ChannelledSocket->Amp\Ipc\Sync{closure}()
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #8 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Coroutine.php(95): Generator->send(Object(Amp\Ipc\Sync\ChannelCloseReq))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #9 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Internal/Placeholder.php(128): Amp\Coroutine->Amp{closure}(NULL, Object(Amp\Ipc\Sync\ChannelCloseReq))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #10 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Coroutine.php(99): Amp\Coroutine->resolve(Object(Amp\Ipc\Sync\ChannelCloseReq))
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #11 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Internal/Placeholder.php(128): Amp\Coroutine->Amp{closure}(NULL, '\x00(\x00\x00\x00O:28:"Amp\...')
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #12 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Deferred.php(52): class@anonymous->resolve('\x00(\x00\x00\x00O:28:"Amp\...')
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #13 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/byte-stream/lib/ResourceInputStream.php(76): Amp\Deferred->resolve('\x00(\x00\x00\x00O:28:"Amp\...')
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #14 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Loop/NativeDriver.php(268): Amp\ByteStream\ResourceInputStream::Amp\ByteStream{closure}('n', Resource id #342, NULL)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #15 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Loop/NativeDriver.php(100): Amp\Loop\NativeDriver->selectStreams(Array, Array, 0)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #16 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Loop/Driver.php(117): Amp\Loop\NativeDriver->dispatch(false)
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: #17 /home/sites/test/web/src/addons/Messaging/vendor/phabel-transpiler74.amphp/amp/lib/Loop/Driver.php(61): Amp\Loop\Driver->tick()

[shawn-digitalpoint]

Been able to pretty consistently reproduce this. If I let MadelineProto session sit idle for a day or two and then try a command, it will Exception with the "Could not connect to DC 1". Immediate restart of the process and all is well again.

Is there something underlying in the protocol where a client is told it should reconnect (or switch data centers) and MadelineProto isn't doing that or something? Or a situation where Telegram data center's disconnect a client if it's idle for a certain amount of time (and MadelineProto assumes it's still connected)?

Have been thinking about working around it by catching the exception, but can't really do that because it seems you can't completely teardown an API to restart it because the settings files keep being written to even after the API class is torn down. See this: #992

MadelineProto being unable to connect to the data center (until the API is restarted) for whatever reason seems like something that should be caught and handled in MadelineProto itself.

[danog]

What do your full logs say?

[shawn-digitalpoint]

The log immediately before the part I posted is this:

Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Logger: MadelineProto
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Logger: Copyright (C) 2016-2020 Daniil Gentili
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Logger: Licensed under AGPLv3
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Logger: https://github.com/danog/MadelineProto
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: SessionPaths: Waiting for shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.lightState.php.lock...
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: SessionPaths: Got shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.lightState.php.lock...
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Server: Starting IPC server /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper (process)
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: ProcessRunner: Starting process with '/usr/local/bin/php' '-dhtml_errors=0' '-ddisplay_errors=0' '-dlog_errors=1' '/home/sites/test/web/src/addons/Messaging/vendor/danog/madelineproto/src/danog/MadelineProto/Ipc/Runner/entry.php' 'madeline-ipc' '/home/sites/test/web/internal_data/madelineproto/madeline-session-0->
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: SessionPaths: Waiting for shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.ipcState.php.lock...
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: SessionPaths: Got shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.ipcState.php.lock...
Mar 18 14:14:30 host1 WebSocketServer.php[11995]: Serialization: MadelineProto is starting, please wait...
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: MadelineProto[0]: getSelf
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: SessionPaths: Waiting for shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.ipcState.php.lock...
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: SessionPaths: Got shared lock of /home/sites/test/web/internal_data/madelineproto/madeline-session-0-helper.ipcState.php.lock...
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: Server: IPC server started successfully!
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: Serialization: MadelineProto is starting, please wait...
Mar 18 14:14:52 host1 WebSocketServer.php[11995]: Serialization: Connected to IPC socket!
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: MadelineProto[0]: getSelf
Mar 22 11:01:36 host1 WebSocketServer.php[11995]: ProcessRunner: Got message from worker: \danog\MadelineProto\Exception: Could not connect to DC 1 in /home/sites/texpert.io/web/src/addons/DigitalPoint/Messaging/vendor/danog/madelineproto/src/danog/MadelineProto/DataCenter.php:300

The last 2 lines from this is the first two lines of the portion in first post. The lines that start with "MadelineProto[0]:" is the daemon logging the method it's sending to MadelineProto.

If you need a different logging level, let me know... can set that and wait a couple days to get a more verbose log.

[danog]

I need the MadelineProto.log file here

[shawn-digitalpoint]

Here's what it has currently... looks like it's probably truncating itself, so not sure if the right part is in there. If you'd like me to set different logging level or parameters for the log, let me know.

MadelineProto.log

[danog]

Should be fixed in the latest version of MadelineProto, if not please open a new issue.