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.

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

Subscriptions stop working after redis reconnect #409

Open
rikvdlooi opened this issue Oct 23, 2024 · 8 comments
Open

Subscriptions stop working after redis reconnect #409

rikvdlooi opened this issue Oct 23, 2024 · 8 comments

Comments

@rikvdlooi
Copy link

We are running our meteor app on Azure with Container Apps. We are having a separate issue with Azure where the connection to Redis is closing and reconnecting a lot of times. We are in contact with Azure people to fix that issue.

10/23/2024, 7:46:16.236 AM RedisOplog - Established connection to redis.
10/23/2024, 7:46:15.609 AM RedisOplog - Connection to redis ended
10/23/2024, 7:46:15.609 AM RedisOplog - There was an error when re-connecting to redis {"delay":100,"attempt":1,"error":{"errno":-110,"code":"ETIMEDOUT","syscall":"read"},"total_retry_time":0,"times_connected":198}

However after such a reconnect, sometimes (?) the subscriptions are not working anymore.

Description of what we see:

  • One one instance of our app (not on Azure) I update an entity (updating the position.x and position.y of a table in this example)
  • The change is published to redis, I confirmed this with redis-cli
  • However on the second instance of our app (which is on Azure), the change to the table is not seen, it remains on it's old position

Updating the position is just an example. Any other updates also do not seem to work. But this is just the most easy thing to test for us.

Because this issue does not happen always, it's hard to reproduce it, and figure out the conditions of why this is happening. We're still actively debugging this ourselves. I'm posting here to check if maybe someone has experienced something similar before, or can point us in the right direction. Or maybe help us isolate the issue, because our logs are quite noisy at the moment.

We have enabled debug, and through the logs it seems that the update to tables is actually received. However the update to the specific table id is ignored (once).

Config

Our config

  "redisOplog": {
    "redis": {
      "url": "xxxx"
    },
    "debug": true,
    "externalRedisPublisher": true,
    "globalRedisPrefix": "production.",
    "mutationDefaults": {
      "optimistic": true,
      "pushToRedis": true
    }
  }

We've set externalRedisPublisher to true because we are using changestream-to-redis by @radekmie.
That seems to be working fine, as through redis-cli I can confirm that the changes are published.

Logs

"TimeGenerated [UTC]","Log_s"
"10/23/2024, 7:46:15.609 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:46:15.609 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":198}"
"10/23/2024, 7:46:16.236 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:46:57.276 AM","[1729669616574] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:17.482 AM","[1729669692668] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:13.311 AM","[1729669753016] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:14.199 AM","[1729669753253] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:28.232 AM","[1729669767370] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:28.232 AM","[1729669767651] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:30.375 AM","[1729669769417] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:30.375 AM","[1729669769858] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:46.193 AM","[1729669785535] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:17.528 AM","[1729669866114] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:17.528 AM","[1729669866582] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:10.301 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:53:09.370 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:53:09.370 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":172}"
"10/23/2024, 7:53:41.361 AM","[1729670021166] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:01.394 AM","[1729670040582] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:01.394 AM","[1729670041075] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:10.305 AM","[1729670041250] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:16.337 AM","[1729670055189] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:16.337 AM","[1729670055431] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:16.337 AM","[1729670055466] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:16.337 AM","[1729670055885] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:16.337 AM","[1729670055964] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:31.306 AM","[1729670070618] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:31.306 AM","[1729670071075] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:31.306 AM","[1729670071165] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:32.345 AM","[1729670071548] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:34.342 AM","[1729670073545] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:35.310 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:54:42.370 AM","[1729670081269] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:02.931 AM","[1729670099408] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:20.435 AM","[1729670120028] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:21.598 AM","[1729670120468] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:21.598 AM","[1729670120841] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:22.366 AM","[1729670121341] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:34.431 AM","[1729670134037] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:58.457 AM","[1729670157577] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:56:07.384 AM","[1729670166355] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:15.314 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:57:15.314 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":199}"
"10/23/2024, 7:57:15.314 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:57:46.183 AM","[1729670265491] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:42.425 AM","[1729670261525] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:42.425 AM","[1729670261533] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:18.564 AM","[1729670293654] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:18.501 AM","[1729670298023] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:12.272 AM","[1729670291716] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:12.272 AM","[1729670291945] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:23.135 AM","[1729670298460] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:23.135 AM","[1729670298540] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:23.135 AM","[1729670298999] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:44.224 AM","[1729670323239] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:47.174 AM","[1729670326446] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:50.420 AM","[1729670329297] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:47.702 AM","[1729670386399] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:01.330 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:36:01.330 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":169}"
"10/23/2024, 7:36:01.330 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:39:10.181 AM","[1729669149144] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:20.329 AM","[1729669159380] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:40:03.251 AM","[1729669202143] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:40:03.251 AM","[1729669202298] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:32.289 AM","[1729669591754] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:32.289 AM","[1729669592064] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:32.154 AM","[1729669591761] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:38.385 AM","[1729669597342] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:43.279 AM","[1729669602999] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:43.386 AM","[1729669602992] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:59.378 AM","[1729669619078] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:01.159 AM","[1729669620103] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:07.188 AM","[1729669627030] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:12.819 AM","[1729669630648] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:12.834 AM","[1729669630972] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:29.186 AM","[1729669648555] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:29.186 AM","[1729669649020] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:30.378 AM","[1729669649101] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:30.378 AM","[1729669649534] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.279 AM","[1729669672394] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:56.250 AM","[1729669675919] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677317] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677397] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677425] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677443] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677581] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:58.193 AM","[1729669677889] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:57.200 AM","[1729669676885] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:03.224 AM","[1729669683005] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:11.192 AM","[1729669690287] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:11.192 AM","[1729669690611] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:12.195 AM","[1729669691546] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:12.195 AM","[1729669691753] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:12.195 AM","[1729669691863] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:33.317 AM","[1729669712687] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:33.317 AM","[1729669712918] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:07.179 AM","[1729669746244] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:45.213 AM","[1729669784625] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:45.213 AM","[1729669784972] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:42.454 AM","[1729670021329] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:52.358 AM","[1729670031520] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:52.358 AM","[1729670031905] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:57.761 AM","[1729670036343] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:58.394 AM","[1729670037495] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:58.394 AM","[1729670037653] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:32:38.293 AM","[1729668758026] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:32:51.460 AM","[1729668770627] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:05.397 AM","[1729668964511] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:05.397 AM","[1729668965010] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:16.403 AM","[1729668975221] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:16.403 AM","[1729668976045] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:15.307 AM","[1729668975128] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:34.372 AM","[1729668993540] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:34.372 AM","[1729668993631] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:32.400 AM","[1729668991349] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:32.400 AM","[1729668991737] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:41.347 AM","[1729669000255] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:41.347 AM","[1729669001128] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:41.921 AM","[1729669000158] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:37:03.397 AM","[1729669022466] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:37:03.397 AM","[1729669022773] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:38:05.374 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:38:20.364 AM","[1729669099852] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:38:24.291 AM","[1729669103442] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:38:58.316 AM","[1729669138055] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:01.590 AM","[1729669141082] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:46.184 AM","[1729669185062] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:46.184 AM","[1729669185618] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:52.362 AM","[1729669191627] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:52.362 AM","[1729669191884] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:52.362 AM","[1729669192039] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:40:02.232 AM","[1729669201194] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:45:10.374 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:45:10.374 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":171}"
"10/23/2024, 7:48:37.971 AM","[1729669714192] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:53:23.342 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:53:23.342 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-104,""code"":""ECONNRESET"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":170}"
"10/23/2024, 7:54:03.374 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:54:03.374 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-104,""code"":""ECONNRESET"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":173}"
"10/23/2024, 7:54:17.341 AM","[1729670057108] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:33.343 AM","[1729670072522] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:33.343 AM","[1729670073024] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:54:33.343 AM","[1729670073105] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:02.297 AM","[1729670101755] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:02.297 AM","[1729670101853] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:55:52.318 AM","[1729670151623] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:56:05.410 AM","[1729670164527] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:56:05.410 AM","[1729670165067] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:56:05.410 AM","[1729670165152] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:18.246 AM","[1729670237672] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:18.489 AM","[1729670237685] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:22.541 AM","[1729670241750] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:22.231 AM","[1729670241738] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:57:39.299 AM","[1729670258185] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:02.200 AM","[1729670281790] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:02.200 AM","[1729670281798] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:31.329 AM","[1729670310481] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:31.329 AM","[1729670310858] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:38.185 AM","[1729670317481] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:43.996 AM","[1729670322794] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:37.240 AM","[1729670436332] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:37.240 AM","[1729670436442] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:11.281 AM","[1729668970839] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:36:11.281 AM","[1729668970935] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:37:23.310 AM","[1729669042512] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:37:29.311 AM","[1729669048301] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:37:29.311 AM","[1729669048615] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:07.225 AM","RedisOplog - Connection to redis ended"
"10/23/2024, 7:39:07.225 AM","RedisOplog - There was an error when re-connecting to redis {""delay"":100,""attempt"":1,""error"":{""errno"":-110,""code"":""ETIMEDOUT"",""syscall"":""read""},""total_retry_time"":0,""times_connected"":197}"
"10/23/2024, 7:39:08.241 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:39:23.342 AM","[1729669162323] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:23.342 AM","[1729669162803] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:23.342 AM","[1729669162891] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:24.253 AM","[1729669163266] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:45.470 AM","[1729669184560] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:39:45.470 AM","[1729669184977] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:45:22.425 AM","[1729669521842] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:45:22.425 AM","[1729669522148] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:45:38.411 AM","RedisOplog - Established connection to redis."
"10/23/2024, 7:45:35.349 AM","[1729669534383] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:33.264 AM","[1729669592071] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:38.349 AM","[1729669597349] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:56.222 AM","[1729669615777] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:56.422 AM","[1729669615770] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:57.445 AM","[1729669616567] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:57.445 AM","[1729669617162] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:58.647 AM","[1729669617321] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.252 AM","[1729669619085] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.252 AM","[1729669619516] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.252 AM","[1729669619598] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.319 AM","[1729669619509] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.319 AM","[1729669619591] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:00.319 AM","[1729669620096] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:58.238 AM","[1729669617169] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:46:58.238 AM","[1729669617328] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:13.317 AM","[1729669632839] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:13.317 AM","[1729669633043] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:16.225 AM","[1729669635582] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:16.225 AM","[1729669635855] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:35.220 AM","[1729669654740] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:49.282 AM","[1729669668285] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:47:49.282 AM","[1729669668538] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:48:04.367 AM","[1729669683208] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:23.210 AM","[1729669762083] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:23.210 AM","[1729669762273] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:31.320 AM","[1729669770080] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:31.320 AM","[1729669770721] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:49:33.236 AM","[1729669772114] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:23.280 AM","[1729669822446] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:53.197 AM","[1729669852085] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:53.197 AM","[1729669852322] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:35.259 AM","[1729669834979] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:38.162 AM","[1729669837966] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:51.170 AM","[1729669850176] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:50:51.942 AM","[1729669849932] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:04.644 AM","[1729669863589] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:04.644 AM","[1729669863825] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:06.260 AM","[1729669865558] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:51:06.260 AM","[1729669866027] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:01.332 AM","[1729670280112] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:58:47.379 AM","[1729670326467] - [RedisSubscriptionManager] Ignored (no subscribers) event: ""u"" to ""production.tables::PrbugmsJR8PtMwy2Q"""
"10/23/2024, 7:58:47.379 AM","[1729670326467] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:06.225 AM","[1729670345229] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:25.228 AM","[1729670364449] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:28.424 AM","[1729670368045] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:31.619 AM","[1729670370734] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:32.568 AM","[1729670372022] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:35.274 AM","[1729670374153] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:34.171 AM","[1729670373347] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:37.214 AM","[1729670376056] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:40.165 AM","[1729670379533] - [RedisSubscriptionManager] Received event: ""i"" to ""production.tables"""
"10/23/2024, 7:59:50.424 AM","[1729670389654] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:50.424 AM","[1729670389806] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:50.424 AM","[1729670389938] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:51.250 AM","[1729670390108] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:51.250 AM","[1729670390187] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:51.250 AM","[1729670390287] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:53.293 AM","[1729670393010] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:58.485 AM","[1729670396384] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:58.485 AM","[1729670396961] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:58.290 AM","[1729670397178] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:58.290 AM","[1729670397289] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 7:59:58.290 AM","[1729670397738] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:03.311 AM","[1729670402543] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:05.276 AM","[1729670404960] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:08.239 AM","[1729670407685] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:06.488 AM","[1729670405181] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:06.488 AM","[1729670405697] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:06.488 AM","[1729670405797] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:18.306 AM","[1729670417307] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:21.500 AM","[1729670420115] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:21.500 AM","[1729670420671] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:21.500 AM","[1729670420754] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:22.277 AM","[1729670421105] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:42.253 AM","[1729670441113] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:41.297 AM","[1729670440165] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:41.297 AM","[1729670440623] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:41.297 AM","[1729670440705] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:53.236 AM","[1729670452371] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:52.286 AM","[1729670451239] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:52.286 AM","[1729670451676] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:52.286 AM","[1729670451756] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:57.338 AM","[1729670456083] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:57.338 AM","[1729670456306] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:59.219 AM","[1729670458186] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:00:59.219 AM","[1729670458556] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:06.199 AM","[1729670465701] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:03.215 AM","[1729670462726] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:07.254 AM","[1729670466172] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:07.254 AM","[1729670466445] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:05.184 AM","[1729670464807] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:09.174 AM","[1729670468757] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:01:26.512 AM","[1729670485726] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:07.204 AM","[1729670526072] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:07.204 AM","[1729670526515] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:07.204 AM","[1729670526598] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:07.204 AM","[1729670527052] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:15.618 AM","[1729670534994] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:16.230 AM","[1729670535147] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:21.252 AM","[1729670540735] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:27.216 AM","[1729670546879] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:26.275 AM","[1729670545147] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:25.281 AM","[1729670544524] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:25.281 AM","[1729670544732] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""
"10/23/2024, 8:02:25.281 AM","[1729670545040] - [RedisSubscriptionManager] Received event: ""u"" to ""production.tables"""

Extra logging

The Ignored (no subscribers) is a custom debug we added in the process method of the RedisSubscriptionManager.js file

        let isSynthetic = data[RedisPipe.SYNTHETIC];

        // messages from redis that contain our uid were handled
        // optimistically, so we can drop them.
        if (fromRedis && data[RedisPipe.UID] === this.uid) {
            debug(
                `[RedisSubscriptionManager] Ignored (same UID) ${
                    isSynthetic ? 'synthetic ' : ''
                }event: "${data[RedisPipe.EVENT]}" to "${channel}"`
            )
            return;
        }

        const subscribers = this.store[channel];
        if (!subscribers) {
            debug(
                `[RedisSubscriptionManager] Ignored (no subscribers) ${
                    isSynthetic ? 'synthetic ' : ''
                }event: "${data[RedisPipe.EVENT]}" to "${channel}"`
            )
            return;
        }

        debug(
            `[RedisSubscriptionManager] Received ${
                isSynthetic ? 'synthetic ' : ''
            }event: "${data[RedisPipe.EVENT]}" to "${channel}"`
        );
Copy link

Thank you for submitting this issue!

We, the Members of Meteor Community Packages take every issue seriously.
Our goal is to provide long-term lifecycles for packages and keep up
with the newest changes in Meteor and the overall NodeJs/JavaScript ecosystem.

However, we contribute to these packages mostly in our free time.
Therefore, we can't guarantee you issues to be solved within certain time.

If you think this issue is trivial to solve, don't hesitate to submit
a pull request, too! We will accompany you in the process with reviews and hints
on how to get development set up.

Please also consider sponsoring the maintainers of the package.
If you don't know who is currently maintaining this package, just leave a comment
and we'll let you know

@rikvdlooi
Copy link
Author

Okay, it seems that the [RedisSubscriptionManager] Received event: "u" to "production.tables" log lines that do show up are old ones.

We just experienced the issue again, and no new lines are logged for [RedisSubscriptionManager] Received event: "u" to "production.tables".

@rikvdlooi
Copy link
Author

It happened again, and more info.

So we received the last update at 10:16:55.620 AM
Then a few logs from the same server instance, so I'll ignore that
Then at 10:36:11.669 AM

RedisOplog - There was an error when re-connecting to redis {"delay":100,"attempt":1,"error":{"errno":-110,"code":"ETIMEDOUT","syscall":"read"},"total_retry_time":0,"times_connected":2}

So after 20 minutes it noticed that the redis connection had timed out. After which it established a new connection at 10/23/2024, 10:36:12.601 AM, and things work again

@edemaine
Copy link

FWIW, this sounds like #365. Unfortunately I've never found a fix; I just have to restart my Meteor servers occasionally. It would be great to get more attention on this and finally track down a solution.

@rikvdlooi
Copy link
Author

Yes, that indeed sounds like the same problem indeed.

I have not been able to find more information as of now.

It seems that we have two different problems, one where the TCP connection times out, after ~20 minutes(!), after which it reconnects. This is most probably an Azure issue.

And the second problem is that when a reconnect happens sometimes it does not "activate" the existing subscriptions again. That sounds like #365.

I've spent most of my time today hunting the first problem. But when I get more info on the second problem I'll update here.

Thanks for your comment.

@ldepaiva
Copy link

Hey @rikvdlooi, I'd like to know if you have any news on this issue. I'm also using Azure with Container Apps, and I'm having a similar problem where the subscription initializes and stops immediately after. Then, it tries to initialize again but never gets ready or returns any data. I have a "testing" system running on Digital Ocean, and it works fine there, using precisely the same image and setup. I appreciate what you've done already on this!

image

@rikvdlooi
Copy link
Author

So an update from our side. I've not been working on this issue for some time, but my colleagues have been testing more.

It seems that Azure ContainerApps is doing something funky with it's connections. We're not sure what is happening, we've Azure support but they weren't able to help any further as well.

We've implemented ioredis, and configured pings + short timeouts for connections and reconnections, and things seem to be working okay now. It now detects a lot better/faster that the connection is (slightly) broken, and does a reconnect with a new connection.

We think that linux does not properly detect that the connection is (slightly) broken, and it takes a long time before it notices that the connection can not be used. But with the workarounds configured (short timeouts + ping) in ioredis this seems to be handled.

My colleague (@jdgjsag67251) will make a pull request this week with the changes we made. Be aware that we use an external publisher, so we only use this redis-oplog package to read from redis.

@jdgjsag67251
Copy link

Hi, our changes can be found here: https://github.com/jdgjsag67251/redis-oplog/tree/ioredis

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants