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.

Sign up for GitHub

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

Jump to bottom

Do not recover from network outage #929

Open
Knud3 opened this issue Sep 2, 2023 · 1 comment
Open

Do not recover from network outage #929

Knud3 opened this issue Sep 2, 2023 · 1 comment

Comments

@Knud3
Copy link

Knud3 commented Sep 2, 2023

If network outage occur, users won't receive new messages even network is up again.

Matrix itself and e.g. mautrix-signal will continue to work even after network outage.

Workaround is to send message to any Telegram room to get every new message to every rooms.

Everything is running in Docker containers with latest versions.

Here is log lines. 3am network outage:

[2023-08-28 03:00:41,269] [INFO@telethon.0000000002.client.updates] Getting difference for account updates (seq: 687, pts: 91593, qts: 0, date: 2023-08-28 02:45:41+00:00)
[2023-08-28 03:01:21,283] [INFO@telethon.0000000002.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 03:01:21,284] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:01:21,484] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 03:01:21,485] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:01:23,578] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:23,578] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:26,650] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:29,722] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:29,722] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:32,794] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:32,794] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:35,866] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:35,866] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:38,938] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:38,938] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:39,940] [INFO@telethon.0000000002.network.mtprotosender] Failed reconnection attempt 1 with ConnectionError
[2023-08-28 03:01:40,942] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:01:42,010] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:42,010] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:43,012] [INFO@telethon.0000000003.network.mtprotosender] Failed reconnection attempt 1 with ConnectionError
[2023-08-28 03:01:44,014] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:01:45,082] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:45,082] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:48,154] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:48,154] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:51,226] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:51,226] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:54,298] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:54,298] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:57,370] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:57,370] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:01:58,372] [INFO@telethon.0000000002.network.mtprotosender] Failed reconnection attempt 2 with ConnectionError
[2023-08-28 03:01:59,374] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:00,442] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:00,442] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:01,444] [INFO@telethon.0000000003.network.mtprotosender] Failed reconnection attempt 2 with ConnectionError
[2023-08-28 03:02:02,445] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:03,514] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:03,514] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:06,586] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:06,586] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:09,658] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:09,658] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:12,730] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:12,730] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:15,802] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:15,802] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:16,804] [INFO@telethon.0000000002.network.mtprotosender] Failed reconnection attempt 3 with ConnectionError
[2023-08-28 03:02:17,806] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:18,874] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:18,874] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:19,876] [INFO@telethon.0000000003.network.mtprotosender] Failed reconnection attempt 3 with ConnectionError
[2023-08-28 03:02:20,879] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:21,946] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:21,946] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:25,018] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:25,018] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:28,090] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:28,090] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:31,161] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:31,161] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:34,234] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:34,234] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:35,236] [INFO@telethon.0000000002.network.mtprotosender] Failed reconnection attempt 4 with ConnectionError
[2023-08-28 03:02:36,238] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:37,306] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:37,306] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:38,308] [INFO@telethon.0000000003.network.mtprotosender] Failed reconnection attempt 4 with ConnectionError
[2023-08-28 03:02:39,311] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:40,378] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:40,378] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 1 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:41,271] [INFO@telethon.0000000002.client.updates] Cannot get difference since the network is down: TimeoutError:
[2023-08-28 03:02:43,450] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:43,450] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 2 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:46,273] [INFO@telethon.0000000002.client.updates] Getting difference for account updates (seq: 687, pts: 91593, qts: 0, date: 2023-08-28 02:45:41+00:00)
[2023-08-28 03:02:46,522] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:46,522] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 3 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:49,594] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:49,594] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 4 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:52,665] [WARNING@telethon.0000000002.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:52,666] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 5 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:53,667] [INFO@telethon.0000000002.network.mtprotosender] Failed reconnection attempt 5 with ConnectionError
[2023-08-28 03:02:54,670] [ERROR@telethon.0000000002.network.mtprotosender] Automatic reconnection failed 5 time(s)
[2023-08-28 03:02:54,670] [INFO@telethon.0000000002.network.mtprotosender] Disconnecting from 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:54,670] [INFO@telethon.0000000002.network.mtprotosender] Disconnection from 149.154.167.91:443/TcpFull complete!
[2023-08-28 03:02:55,738] [WARNING@telethon.0000000003.network.mtprotosender] Attempt 6 at connecting failed: OSError: [Errno 113] Connect call failed ('149.154.167.91', 443)
[2023-08-28 03:02:56,738] [INFO@telethon.0000000003.network.mtprotosender] Failed reconnection attempt 5 with ConnectionError
[2023-08-28 03:02:57,740] [ERROR@telethon.0000000003.network.mtprotosender] Automatic reconnection failed 5 time(s)
[2023-08-28 03:02:57,741] [INFO@telethon.0000000003.network.mtprotosender] Disconnecting from 149.154.167.91:443/TcpFull...
[2023-08-28 03:02:57,741] [INFO@telethon.0000000003.network.mtprotosender] Disconnection from 149.154.167.91:443/TcpFull complete!
[2023-08-28 03:04:46,285] [INFO@telethon.0000000002.client.updates] Cannot get difference since the network is down: TimeoutError:
[2023-08-28 03:04:51,291] [INFO@telethon.0000000002.client.updates] Update loop finished
[2023-08-28 03:14:08,458] [INFO@telethon.0000000003.client.updates] Update loop finished
[2023-08-28 06:02:04,600] [DEBUG@mau.as] Handling transaction 87935 with 4 EDUs
[2023-08-28 06:02:04,601] [DEBUG@mau.as] Finished handling transaction 87935
[2023-08-28 06:02:04,602] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:02:04 +0000] "PUT /_matrix/app/v1/transactions/87935 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 06:22:03,147] [DEBUG@mau.as] Handling transaction 87939 with 4 EDUs
[2023-08-28 06:22:03,147] [DEBUG@mau.as] Finished handling transaction 87939
[2023-08-28 06:22:03,148] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:22:03 +0000] "PUT /_matrix/app/v1/transactions/87939 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 06:22:03,181] [DEBUG@mau.as] Handling transaction 87942 with 1 EDUs
[2023-08-28 06:22:03,182] [DEBUG@mau.as] Finished handling transaction 87942
[2023-08-28 06:22:03,182] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:22:03 +0000] "PUT /_matrix/app/v1/transactions/87942 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 06:32:49,151] [DEBUG@mau.as] Handling transaction 87945 with 4 EDUs
[2023-08-28 06:32:49,152] [DEBUG@mau.as] Finished handling transaction 87945
[2023-08-28 06:32:49,152] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:32:49 +0000] "PUT /_matrix/app/v1/transactions/87945 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 06:32:49,180] [DEBUG@mau.as] Handling transaction 87948 with 1 EDUs
[2023-08-28 06:32:49,180] [DEBUG@mau.as] Finished handling transaction 87948
[2023-08-28 06:32:49,180] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:32:49 +0000] "PUT /_matrix/app/v1/transactions/87948 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 06:37:40,233] [DEBUG@mau.as] Handling transaction 87951 with 5 EDUs
[2023-08-28 06:37:40,234] [DEBUG@mau.as] Finished handling transaction 87951
[2023-08-28 06:37:40,235] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:06:37:40 +0000] "PUT /_matrix/app/v1/transactions/87951 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:29:49,311] [DEBUG@mau.as] Handling transaction 87959 with 1 EDUs
[2023-08-28 07:29:49,311] [DEBUG@mau.as] Finished handling transaction 87959
[2023-08-28 07:29:49,312] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:29:49 +0000] "PUT /_matrix/app/v1/transactions/87959 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:29:53,021] [DEBUG@mau.as] Handling transaction 87960 with 1 EDUs
[2023-08-28 07:29:53,021] [DEBUG@mau.as] Finished handling transaction 87960
[2023-08-28 07:29:53,022] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:29:53 +0000] "PUT /_matrix/app/v1/transactions/87960 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:29:53,207] [DEBUG@mau.as] Handling transaction 87961 with 1 PDUs
[2023-08-28 07:29:53,208] [DEBUG@mau.as] Finished handling transaction 87961
[2023-08-28 07:29:53,208] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:29:53 +0000] "PUT /_matrix/app/v1/transactions/87961 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:29:53,230] [DEBUG@mau.crypto] Ratchet safety info for *SNIP*: RatchetSafety(next_index=5, missed_indices=[], lost_indices=[]), ratchet_target_index=5
[2023-08-28 07:29:53,252] [DEBUG@mau.user.@user2:example.com] Starting client due to ensure_started(even_if_no_session=False, session_exists=True)
[2023-08-28 07:29:53,252] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:29:53,284] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:29:53,544] [INFO@telethon.0000000003.client.telegrambaseclient] Ensuring user is still in *SNIP*
[2023-08-28 07:29:53,590] [INFO@telethon.0000000003.client.telegrambaseclient] Ensuring user is still in *SNIP*
[2023-08-28 07:29:53,630] [DEBUG@mau.user.@user2:example.com] @user2:example.com connected: True
[2023-08-28 07:29:53,630] [INFO@telethon.0000000003.client.updates] Update loop starting
[2023-08-28 07:29:53,631] [INFO@telethon.0000000003.client.updates] Getting difference for account updates (seq: 984, pts: 46501, qts: 0, date: 2023-08-28 02:59:08+00:00)
[2023-08-28 07:29:53,668] [DEBUG@mau.user.@user2:example.com] Ensuring post_login() for @user2:example.com
[2023-08-28 07:29:53,668] [DEBUG@mau.mx] Received Matrix event *SNOP* from @user2:example.com in *SNIP*:example.com
[2023-08-28 07:29:53,669] [INFO@telethon.0000000003.client.updates] New account state after applying difference (DifferenceEmpty): seq: 984, pts: 46501, qts: 0, date: 2023-08-28 07:29:53+00:00
[2023-08-28 07:29:53,822] [DEBUG@mau.portal.0000000003<->0000000002] Handled Matrix message *SNIP* -> 29207 (edit index 0)
[2023-08-28 07:30:53,639] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:30:53,640] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:30:53,671] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:31:53,676] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:31:53,677] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:31:53,709] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:32:53,720] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:32:53,721] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:32:53,753] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:33:19,229] [DEBUG@mau.as] Handling transaction 87964 with 5 EDUs
[2023-08-28 07:33:19,230] [DEBUG@mau.as] Finished handling transaction 87964
[2023-08-28 07:33:19,231] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:33:19 +0000] "PUT /_matrix/app/v1/transactions/87964 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:33:19,242] [DEBUG@mau.as] Handling transaction 87967 with 1 EDUs
[2023-08-28 07:33:19,243] [DEBUG@mau.as] Finished handling transaction 87967
[2023-08-28 07:33:19,243] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:33:19 +0000] "PUT /_matrix/app/v1/transactions/87967 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:33:53,762] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:33:53,762] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:33:53,798] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:34:53,789] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:34:53,791] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:34:53,827] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:35:53,835] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:35:53,835] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:35:53,870] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:36:53,861] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:36:53,862] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:36:53,896] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:37:10,626] [DEBUG@mau.as] Handling transaction 87971 with 5 EDUs
[2023-08-28 07:37:10,626] [DEBUG@mau.as] Finished handling transaction 87971
[2023-08-28 07:37:10,627] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:37:10 +0000] "PUT /_matrix/app/v1/transactions/87971 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:37:10,638] [DEBUG@mau.as] Handling transaction 87973 with 1 EDUs
[2023-08-28 07:37:10,638] [DEBUG@mau.as] Finished handling transaction 87973
[2023-08-28 07:37:10,638] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:37:10 +0000] "PUT /_matrix/app/v1/transactions/87973 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:37:53,893] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:37:53,894] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:37:53,925] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:38:53,934] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:38:53,935] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:38:53,966] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:38:54,170] [DEBUG@mau.as] Handling transaction 87976 with 5 EDUs
[2023-08-28 07:38:54,170] [DEBUG@mau.as] Finished handling transaction 87976
[2023-08-28 07:38:54,171] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:38:54 +0000] "PUT /_matrix/app/v1/transactions/87976 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:38:56,419] [DEBUG@mau.as] Handling transaction 87979 with 1 EDUs
[2023-08-28 07:38:56,419] [DEBUG@mau.as] Finished handling transaction 87979
[2023-08-28 07:38:56,420] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:38:56 +0000] "PUT /_matrix/app/v1/transactions/87979 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:39:53,970] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:39:53,972] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:39:54,008] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:40:54,002] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:40:54,003] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:40:54,034] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:41:54,042] [INFO@telethon.0000000003.network.mtprotosender] Closing current connection to begin reconnect...
[2023-08-28 07:41:54,043] [INFO@telethon.0000000003.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:41:54,074] [INFO@telethon.0000000003.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:42:05,557] [DEBUG@mau.as] Handling transaction 87980 with 1 PDUs
[2023-08-28 07:42:05,557] [DEBUG@mau.as] Finished handling transaction 87980

User send message to Telegram room and all received messages appear:

[2023-08-28 07:42:05,558] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:42:05 +0000] "PUT /_matrix/app/v1/transactions/87980 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:42:05,564] [DEBUG@mau.crypto] Ratchet safety info for *SNIP*: RatchetSafety(next_index=25, missed_indices=[], lost_indices=[]), ratchet_target_index=25
[2023-08-28 07:42:05,573] [DEBUG@mau.user.@user1:example.com] Starting client due to ensure_started(even_if_no_session=False, session_exists=True)
[2023-08-28 07:42:05,573] [INFO@telethon.0000000002.network.mtprotosender] Connecting to 149.154.167.91:443/TcpFull...
[2023-08-28 07:42:05,608] [INFO@telethon.0000000002.network.mtprotosender] Connection to 149.154.167.91:443/TcpFull complete!
[2023-08-28 07:42:05,697] [INFO@telethon.0000000002.client.telegrambaseclient] Ensuring user is still in *SNIP*
[2023-08-28 07:42:05,750] [DEBUG@mau.user.@user1:example.com] @user1:example.com connected: True
[2023-08-28 07:42:05,751] [INFO@telethon.0000000002.client.updates] Update loop starting
[2023-08-28 07:42:05,751] [INFO@telethon.0000000002.client.updates] Getting difference for account updates (seq: 687, pts: 91593, qts: 0, date: 2023-08-28 02:45:41+00:00)
[2023-08-28 07:42:05,792] [DEBUG@mau.user.@user1:example.com] Ensuring post_login() for @user1:example.com
[2023-08-28 07:42:05,792] [DEBUG@mau.mx] Received Matrix event *SNIP* from @user1:example.com in *SNIP*:example.com
[2023-08-28 07:42:05,805] [INFO@telethon.0000000002.client.updates] New account state after applying difference (Difference): seq: 787, pts: 91595, qts: 0, date: 2023-08-28 07:42:05+00:00
[2023-08-28 07:42:05,877] [DEBUG@mau.portal.0000000002<->0000000001] Handling Telegram message 54332@0000000002 from 0000000001 (ts: 2023-08-28 07:28:08+00:00)
[2023-08-28 07:42:05,948] [DEBUG@mau.portal.0000000002<->0000000003] Handled Matrix message *SNIP* -> 54334 (edit index 0)
[2023-08-28 07:42:05,961] [DEBUG@mau.portal.0000000003<->0000000002] Handling Telegram message 29208@0000000003 from 0000000002 (ts: 2023-08-28 07:42:05+00:00)
[2023-08-28 07:42:06,051] [DEBUG@mau.as.api.@telegram_0000000001:example.com] req #1342: PUT http://synapse:8008/_matrix/client/v3/rooms/*SNIP*example.com/typing/%40telegram_0000000001%3Aexample.com?user_id=@telegram_0000000001:example.com {"typing": false}
[2023-08-28 07:42:06,079] [DEBUG@mau.as.api.@telegram_0000000001:example.com] req #1342 (/v3/rooms/*SNIP*example.com/typing/%40telegram_0000000001%3Aexample.com) completed in 27.2ms with status 200
[2023-08-28 07:42:06,079] [DEBUG@mau.crypto] Encrypting event of type m.room.message for *SNIP*:example.com
[2023-08-28 07:42:06,081] [DEBUG@mau.bridge.e2ee] Got EncryptionError, sharing group session and trying again
[2023-08-28 07:42:06,107] [DEBUG@mau.as.api.@telegram_0000000002:example.com] req #1343: PUT http://synapse:8008/_matrix/client/v3/rooms/*SNIP*example.com/typing/%40telegram_0000000002%3Aexample.com?user_id=@telegram_0000000002:example.com {"typing": false}
[2023-08-28 07:42:06,139] [DEBUG@mau.as.api.@telegram_0000000002:example.com] req #1343 (/v3/rooms/*SNIP*example.com/typing/%40telegram_0000000002%3Aexample.com) completed in 32.6ms with status 200
[2023-08-28 07:42:06,140] [DEBUG@mau.crypto] Encrypting event of type m.room.message for *SNIP*:example.com
[2023-08-28 07:42:06,142] [DEBUG@mau.bridge.e2ee] Got EncryptionError, sharing group session and trying again
[2023-08-28 07:42:06,146] [DEBUG@mau.as] Handling transaction 87981 with 4 EDUs
[2023-08-28 07:42:06,146] [DEBUG@mau.as] Finished handling transaction 87981
[2023-08-28 07:42:06,147] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:42:06 +0000] "PUT /_matrix/app/v1/transactions/87981 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:42:06,167] [DEBUG@mau.as] Handling transaction 87982 with 1 EDUs
[2023-08-28 07:42:06,168] [DEBUG@mau.as] Finished handling transaction 87982
[2023-08-28 07:42:06,168] [INFO@aiohttp.access] 172.18.0.4 [28/Aug/2023:07:42:06 +0000] "PUT /_matrix/app/v1/transactions/87982 HTTP/1.1" 200 159 "-" "Synapse/1.90.0"
[2023-08-28 07:42:06,243] [DEBUG@mau.crypto] Got stored encryption state event and configured session to rotate after 100 messages or 7 days, 0:00:00
[2023-08-28 07:42:06,248] [DEBUG@mau.crypto] Created inbound group session *SNIP*:example.com/*SNIP* (max 7 days, 0:00:00 / 100 messages, is_scheduled=False)
[2023-08-28 07:42:06,248] [DEBUG@mau.crypto] Sharing group session *SNIP* for room *SNIP*:example.com with ['@user1:example.com']
[2023-08-28 07:42:06,252] [DEBUG@mau.crypto] Trying to encrypt group session *SNIP* for @user1:example.com
[2023-08-28 07:42:06,286] [DEBUG@mau.crypto] Sending to-device events to 5 devices of 1 users to share *SNIP*
[2023-08-28 07:42:06,287] [DEBUG@mau.bridge.e2ee.client] req #1344: PUT http://synapse:8008/_matrix/client/v3/sendToDevice/m.room.encrypted/mautrix-python_*SNIP* {"messages": {"@user1:example.com": {"*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}, "*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}, "*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}, "*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}, "*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}}}}
[2023-08-28 07:42:06,297] [DEBUG@mau.crypto] Got stored encryption state event and configured session to rotate after 100 messages or 7 days, 0:00:00
[2023-08-28 07:42:06,303] [DEBUG@mau.crypto] Created inbound group session *SNIP*:example.com/*SNIP*/*SNIP* (max 7 days, 0:00:00 / 100 messages, is_scheduled=False)
[2023-08-28 07:42:06,303] [DEBUG@mau.crypto] Sharing group session *SNIP* for room *SNIP*:example.com with ['@user2:example.com']
[2023-08-28 07:42:06,305] [DEBUG@mau.crypto] Trying to encrypt group session *SNIP* for @user2:example.com
[2023-08-28 07:42:06,307] [DEBUG@mau.bridge.e2ee.client] req #1344 (/v3/sendToDevice/m.room.encrypted/mautrix-python_*SNIP*) completed in 20.6ms with status 200
[2023-08-28 07:42:06,308] [INFO@mau.crypto] Group session *SNIP* for *SNIP*:example.com successfully shared
[2023-08-28 07:42:06,312] [DEBUG@mau.crypto] Encrypting event of type m.room.message for *SNIP*:example.com
[2023-08-28 07:42:06,318] [DEBUG@mau.crypto] Sending to-device events to 1 devices of 1 users to share *SNIP*
[2023-08-28 07:42:06,318] [DEBUG@mau.bridge.e2ee.client] req #1345: PUT http://synapse:8008/_matrix/client/v3/sendToDevice/m.room.encrypted/mautrix-python_*SNIP* {"messages": {"@user2:example.com": {"*SNIP*": {"ciphertext": {"*SNIP*": {"body": "*SNIP*", "type": 1}}, "sender_key": "*SNIP*", "algorithm": "m.olm.v1.curve25519-aes-sha2"}}}}
[2023-08-28 07:42:06,323] [DEBUG@mau.as.api.@telegram_0000000001:example.com] req #1346: PUT http://synapse:8008/_matrix/client/v3/rooms/*SNIP*example.com/send/m.room.encrypted/mautrix-python_*SNIP*?ts=*SNIP*&user_id=@telegram_0000000001:example.com {"ciphertext": "*SNIP*", "session_id": "*SNIP*", "algorithm": "m.megolm.v1.aes-sha2", "sender_key": "*SNIP*", "device_id": "*SNIP*"}
[2023-08-28 07:42:06,331] [DEBUG@mau.bridge.e2ee.client] req #1345 (/v3/sendToDevice/m.room.encrypted/mautrix-python_*SNIP*) completed in 12.0ms with status 200
[2023-08-28 07:42:06,331] [INFO@mau.crypto] Group session *SNIP* for *SNIP*:example.com successfully shared
[2023-08-28 07:42:06,338] [DEBUG@mau.crypto] Encrypting event of type m.room.message for *SNIP*:example.com
[2023-08-28 07:42:06,344] [DEBUG@mau.as.api.@telegram_0000000002:example.com] req #1347: PUT http://synapse:8008/_matrix/client/v3/rooms/*SNIP*example.com/send/m.room.encrypted/mautrix-python_*SNIP*?ts=*SNIP*&user_id=@telegram_0000000002:example.com {"ciphertext": "*SNIP*", "session_id": "*SNIP*", "algorithm": "m.megolm.v1.aes-sha2", "sender_key": "*SNIP*", "device_id": "*SNIP*"}
@ClemensElflein
Copy link

I have the same issue. Noticed it after updating to the latest version.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ClemensElflein @Knud3