0

I have an Azure Web App which is deployed with docker-compose. It runs a Rails app on v5.0.0 and the mongoid version is 6.1.

I've the Always On turned on (how ironic). But after a few moments of idle time, if I refresh a tab with my app already open, or try to access it in a new tab, I land on my Rails error page and the logs look like this :

2020-09-03T14:56:20.036576946Z F, [2020-09-03T14:56:20.036429 #1] FATAL -- :
2020-09-03T14:56:20.037180348Z F, [2020-09-03T14:56:20.036742 #1] FATAL -- : Mongo::Error::SocketTimeoutError (Errno::ETIMEDOUT: Connection timed out (for xxxx:10384 (no TLS)) (on xxxxx.com:10384) (on xxxx.com:10384)):
2020-09-03T14:56:20.037761050Z F, [2020-09-03T14:56:20.037270 #1] FATAL -- :
2020-09-03T14:56:20.038380451Z F, [2020-09-03T14:56:20.037850 #1] FATAL -- : mongo (2.11.4) lib/mongo/socket.rb:326:in `rescue in handle_errors'
2020-09-03T14:56:20.038954453Z F, [2020-09-03T14:56:20.038458 #1] FATAL -- : mongo (2.11.4) lib/mongo/socket.rb:322:in `handle_errors'
2020-09-03T14:56:20.039493755Z F, [2020-09-03T14:56:20.039036 #1] FATAL -- : mongo (2.11.4) lib/mongo/socket.rb:175:in `write'
2020-09-03T14:56:20.040059456Z F, [2020-09-03T14:56:20.039569 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connection_base.rb:107:in `block in deliver'
2020-09-03T14:56:20.040644158Z F, [2020-09-03T14:56:20.040140 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connectable.rb:83:in `ensure_connected'
2020-09-03T14:56:20.041233659Z F, [2020-09-03T14:56:20.040726 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connection_base.rb:100:in `deliver'
2020-09-03T14:56:20.042001062Z F, [2020-09-03T14:56:20.041308 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connection.rb:394:in `deliver'
2020-09-03T14:56:20.042766364Z F, [2020-09-03T14:56:20.042112 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connection_base.rb:93:in `dispatch'
2020-09-03T14:56:20.043390666Z F, [2020-09-03T14:56:20.042861 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:56:in `block in dispatch_message'
2020-09-03T14:56:20.044017767Z F, [2020-09-03T14:56:20.043468 #1] FATAL -- : mongo (2.11.4) lib/mongo/server/connection_pool.rb:557:in `with_connection'
2020-09-03T14:56:20.048727981Z F, [2020-09-03T14:56:20.044099 #1] FATAL -- : mongo (2.11.4) lib/mongo/server.rb:417:in `with_connection'
2020-09-03T14:56:20.049537683Z F, [2020-09-03T14:56:20.048839 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:55:in `dispatch_message'
2020-09-03T14:56:20.050187285Z F, [2020-09-03T14:56:20.049630 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:50:in `get_result'
2020-09-03T14:56:20.050763786Z F, [2020-09-03T14:56:20.050602 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:29:in `block (3 levels) in do_execute'
2020-09-03T14:56:20.051367688Z F, [2020-09-03T14:56:20.050853 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/response_handling.rb:87:in `add_server_diagnostics'
2020-09-03T14:56:20.051939690Z F, [2020-09-03T14:56:20.051446 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:28:in `block (2 levels) in do_execute'
2020-09-03T14:56:20.052551592Z F, [2020-09-03T14:56:20.052046 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/response_handling.rb:43:in `add_error_labels'
2020-09-03T14:56:20.053126093Z F, [2020-09-03T14:56:20.052627 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:27:in `block in do_execute'
2020-09-03T14:56:20.053708795Z F, [2020-09-03T14:56:20.053207 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/response_handling.rb:73:in `unpin_maybe'
2020-09-03T14:56:20.058397008Z F, [2020-09-03T14:56:20.053784 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable.rb:26:in `do_execute'
2020-09-03T14:56:20.058904510Z F, [2020-09-03T14:56:20.058556 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/executable_no_validate.rb:25:in `execute'
2020-09-03T14:56:20.059321611Z F, [2020-09-03T14:56:20.058996 #1] FATAL -- : mongo (2.11.4) lib/mongo/operation/shared/write.rb:38:in `execute'
2020-09-03T14:56:20.059660912Z F, [2020-09-03T14:56:20.059406 #1] FATAL -- : mongo (2.11.4) lib/mongo/collection/view/writable.rb:344:in `block (2 levels) in update_one'
2020-09-03T14:56:20.060140113Z F, [2020-09-03T14:56:20.059739 #1] FATAL -- : mongo (2.11.4) lib/mongo/retryable.rb:293:in `legacy_write_with_retry'
2020-09-03T14:56:20.060993115Z F, [2020-09-03T14:56:20.060369 #1] FATAL -- : mongo (2.11.4) lib/mongo/retryable.rb:202:in `write_with_retry'
2020-09-03T14:56:20.061628817Z F, [2020-09-03T14:56:20.061089 #1] FATAL -- : mongo (2.11.4) lib/mongo/collection/view/writable.rb:332:in `block in update_one'
2020-09-03T14:56:20.062270919Z F, [2020-09-03T14:56:20.061720 #1] FATAL -- : mongo (2.11.4) lib/mongo/client.rb:844:in `with_session'
2020-09-03T14:56:20.062848521Z F, [2020-09-03T14:56:20.062350 #1] FATAL -- : mongo (2.11.4) lib/mongo/collection/view.rb:208:in `with_session'
2020-09-03T14:56:20.063438422Z F, [2020-09-03T14:56:20.062937 #1] FATAL -- : mongo (2.11.4) lib/mongo/collection/view/writable.rb:330:in `update_one'
2020-09-03T14:56:20.063762323Z F, [2020-09-03T14:56:20.063526 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/query_cache.rb:182:in `update_one_with_clear_cache'
2020-09-03T14:56:20.068365936Z F, [2020-09-03T14:56:20.068198 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/updatable.rb:137:in `block in update_document'
2020-09-03T14:56:20.068764737Z F, [2020-09-03T14:56:20.068464 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/updatable.rb:112:in `block (2 levels) in prepare_update'
2020-09-03T14:56:20.069098738Z F, [2020-09-03T14:56:20.068837 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:126:in `call'
2020-09-03T14:56:20.069551040Z F, [2020-09-03T14:56:20.069185 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
2020-09-03T14:56:20.069922541Z F, [2020-09-03T14:56:20.069634 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:455:in `call'
2020-09-03T14:56:20.070301242Z F, [2020-09-03T14:56:20.069985 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
2020-09-03T14:56:20.071079344Z F, [2020-09-03T14:56:20.070762 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:750:in `_run_update_callbacks'
2020-09-03T14:56:20.071965547Z F, [2020-09-03T14:56:20.071321 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:90:in `run_callbacks'
2020-09-03T14:56:20.072571148Z F, [2020-09-03T14:56:20.072053 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/interceptable.rb:132:in `run_callbacks'
2020-09-03T14:56:20.076978661Z F, [2020-09-03T14:56:20.072652 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/updatable.rb:111:in `block in prepare_update'
2020-09-03T14:56:20.081686074Z F, [2020-09-03T14:56:20.077057 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:126:in `call'
2020-09-03T14:56:20.081744074Z F, [2020-09-03T14:56:20.077585 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
2020-09-03T14:56:20.082658577Z F, [2020-09-03T14:56:20.077653 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:455:in `call'
2020-09-03T14:56:20.083267779Z F, [2020-09-03T14:56:20.082740 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
2020-09-03T14:56:20.083847180Z F, [2020-09-03T14:56:20.083678 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:750:in `_run_save_callbacks'
2020-09-03T14:56:20.084433382Z F, [2020-09-03T14:56:20.084262 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:90:in `run_callbacks'
2020-09-03T14:56:20.085056384Z F, [2020-09-03T14:56:20.084519 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/interceptable.rb:132:in `run_callbacks'
2020-09-03T14:56:20.085645385Z F, [2020-09-03T14:56:20.085135 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/updatable.rb:110:in `prepare_update'
2020-09-03T14:56:20.086256487Z F, [2020-09-03T14:56:20.085728 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/updatable.rb:132:in `update_document'
2020-09-03T14:56:20.086857389Z F, [2020-09-03T14:56:20.086334 #1] FATAL -- : mongoid (6.1.1) lib/mongoid/persistable/savable.rb:25:in `save'
2020-09-03T14:56:20.087490791Z F, [2020-09-03T14:56:20.086940 #1] FATAL -- : mongo_session_store (3.2.0) lib/mongo_session_store/mongo_store_base.rb:45:in `set_session'
2020-09-03T14:56:20.092810406Z F, [2020-09-03T14:56:20.091388 #1] FATAL -- : mongo_session_store (3.2.0) lib/mongo_session_store/mongo_store_base.rb:35:in `write_session'
2020-09-03T14:56:20.092929006Z F, [2020-09-03T14:56:20.091652 #1] FATAL -- : rack (2.2.2) lib/rack/session/abstract/id.rb:388:in `commit_session'
2020-09-03T14:56:20.093020206Z F, [2020-09-03T14:56:20.091799 #1] FATAL -- : rack (2.2.2) lib/rack/session/abstract/id.rb:268:in `context'
2020-09-03T14:56:20.093123606Z F, [2020-09-03T14:56:20.092404 #1] FATAL -- : rack (2.2.2) lib/rack/session/abstract/id.rb:260:in `call'
2020-09-03T14:56:20.093215807Z F, [2020-09-03T14:56:20.092578 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/cookies.rb:613:in `call'
2020-09-03T14:56:20.093748708Z F, [2020-09-03T14:56:20.092976 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
2020-09-03T14:56:20.095283913Z F, [2020-09-03T14:56:20.094257 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:97:in `__run_callbacks__'
2020-09-03T14:56:20.096501516Z F, [2020-09-03T14:56:20.095665 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
2020-09-03T14:56:20.097084918Z F, [2020-09-03T14:56:20.096889 #1] FATAL -- : activesupport (5.0.0) lib/active_support/callbacks.rb:90:in `run_callbacks'
2020-09-03T14:56:20.101606130Z F, [2020-09-03T14:56:20.097203 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/callbacks.rb:36:in `call'
2020-09-03T14:56:20.102785134Z F, [2020-09-03T14:56:20.102628 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
2020-09-03T14:56:20.103434636Z F, [2020-09-03T14:56:20.102878 #1] FATAL -- : rollbar (2.24.0) lib/rollbar/middleware/rails/rollbar.rb:25:in `block in call'
2020-09-03T14:56:20.104009437Z F, [2020-09-03T14:56:20.103835 #1] FATAL -- : rollbar (2.24.0) lib/rollbar.rb:145:in `scoped'
2020-09-03T14:56:20.105016440Z F, [2020-09-03T14:56:20.104816 #1] FATAL -- : rollbar (2.24.0) lib/rollbar/middleware/rails/rollbar.rb:22:in `call'
2020-09-03T14:56:20.105651942Z F, [2020-09-03T14:56:20.105104 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
2020-09-03T14:56:20.106241944Z F, [2020-09-03T14:56:20.106036 #1] FATAL -- : rollbar (2.24.0) lib/rollbar/middleware/rails/show_exceptions.rb:22:in `call_with_rollbar'
2020-09-03T14:56:20.106842145Z F, [2020-09-03T14:56:20.106678 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
2020-09-03T14:56:20.107500047Z F, [2020-09-03T14:56:20.106932 #1] FATAL -- : railties (5.0.0) lib/rails/rack/logger.rb:36:in `call_app'
2020-09-03T14:56:20.111858460Z F, [2020-09-03T14:56:20.107577 #1] FATAL -- : railties (5.0.0) lib/rails/rack/logger.rb:26:in `call'
2020-09-03T14:56:20.112389861Z F, [2020-09-03T14:56:20.111949 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/request_id.rb:24:in `call'
2020-09-03T14:56:20.112855762Z F, [2020-09-03T14:56:20.112477 #1] FATAL -- : rack (2.2.2) lib/rack/method_override.rb:24:in `call'
2020-09-03T14:56:20.113393964Z F, [2020-09-03T14:56:20.112924 #1] FATAL -- : rack (2.2.2) lib/rack/runtime.rb:22:in `call'
2020-09-03T14:56:20.114051166Z F, [2020-09-03T14:56:20.113554 #1] FATAL -- : activesupport (5.0.0) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
2020-09-03T14:56:20.114617467Z F, [2020-09-03T14:56:20.114166 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/executor.rb:12:in `call'
2020-09-03T14:56:20.115553970Z F, [2020-09-03T14:56:20.115044 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/static.rb:136:in `call'
2020-09-03T14:56:20.116156172Z F, [2020-09-03T14:56:20.115641 #1] FATAL -- : rack (2.2.2) lib/rack/sendfile.rb:110:in `call'
2020-09-03T14:56:20.116749973Z F, [2020-09-03T14:56:20.116233 #1] FATAL -- : actionpack (5.0.0) lib/action_dispatch/middleware/ssl.rb:83:in `call'
2020-09-03T14:56:20.117397175Z F, [2020-09-03T14:56:20.116843 #1] FATAL -- : railties (5.0.0) lib/rails/engine.rb:522:in `call'
2020-09-03T14:56:20.124842596Z F, [2020-09-03T14:56:20.117480 #1] FATAL -- : puma (3.12.4) lib/puma/configuration.rb:227:in `call'
2020-09-03T14:56:20.124911497Z F, [2020-09-03T14:56:20.121530 #1] FATAL -- : puma (3.12.4) lib/puma/server.rb:675:in `handle_request'
2020-09-03T14:56:20.125030397Z F, [2020-09-03T14:56:20.121722 #1] FATAL -- : puma (3.12.4) lib/puma/server.rb:476:in `process_client'
2020-09-03T14:56:20.125061897Z F, [2020-09-03T14:56:20.121895 #1] FATAL -- : puma (3.12.4) lib/puma/server.rb:334:in `block in run'
2020-09-03T14:56:20.125147297Z F, [2020-09-03T14:56:20.122061 #1] FATAL -- : puma (3.12.4) lib/puma/thread_pool.rb:135:in `block in spawn_thread'

If I refresh my app everything is up again. That's cool but as a client perspective this is not acceptable.

I've tried playing with the socket_timeout option by settying it to an absurde value in my mongoid.yml but it doesn't seem to help much.

It looks like it could come from Azure that cuts connections that are idle for too long but how come my Mongo socket is considered as such ? Am I missing something ?

Any help is kindly appreciated, thanks !

Thr
  • 43
  • 1
  • 5

1 Answers1

0

EDIT : The ruby driver received a commit fixing this issue. Upgrading the ruby driver version should fix the problem. Thanks D. SM for pointing it out.

If you can't / don't want to upgrade your version, the below code seems to work.

After digging everything out of the mongoid and ruby driver doc I've managed to avoid my app crashing after going idle on Read retries with these options on my mongoid.yml :

   socket_timeout: 60
   heartbeat_frequency: 2
   max_idle_time: 1
Thr
  • 43
  • 1
  • 5
  • Those are very low intervals. I suspect if you use the current driver version you won't need to adjust keep-alive settings. – D. SM Sep 07 '20 at 03:24
  • I've thought about upgrading the mongo driver version but wasn't sure if it would have any benefits, do you have some links about the newer versions handling keepalives differently ? And I'm not sure about this but setting the values this low helps resetting the sockets more frequently and thus avoid Azure timing out the mongo sockets. If someone has a better understanding of this situations I'm taking it – Thr Sep 07 '20 at 14:07
  • 1
    You can search the driver source for keep-alive settings, they were changed recently to accommodate azure. – D. SM Sep 07 '20 at 18:52
  • Right ! I missed it though this included a lot of keywords I've been using... For anyone wondering this is the [commit](https://jira.mongodb.org/browse/RUBY-2261) in question I'll edit the main asnwer to display both options – Thr Sep 08 '20 at 06:59