Периодические ошибки тайм-аутов при использовании Enyim/memcached
Мы используем Enyim /memcached и иногда (возможно, несколько раз в день) мы видим ошибки, вызванные таймаутами при чтении из сокетов. Ошибка: " System.IO.IOException: не удалось прочитать из сокета" 10.100.240.129:11211 ". Ошибка: TimedOut ".
Наш код выполняется внутри веб-службы, работающей в IIS, установленной в контейнере Docker. Вот версии:
- Docker 17.06.2-ee5 и ee6, а также некоторые старые версии
- IIS 10
- СервисСтак NuGet версия 4.0.60
- Memstack NuGet версия 2.13.0
Любая идея о том, что может вызвать эту ошибку?
Вот типичный журнал Enyim во время возникновения ошибки:
Time messageId message
10:06:34.635 10,213 Are we alive? True
10:06:34.635 10,214 Action '<Get>b__3' executed. Took 1.9913 ms.
10:06:34.635 10,216 Acquiring stream from pool. 10.100.240.129:11211
10:06:34.635 10,217 Socket 5315212e-7192-4d7e-91c4-f1d8497898b6 was reset
10:06:34.635 10,215 Executing action '<Get>b__3'
10:06:34.634 10,212 Releasing socket 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:34.633 10,208 Executing action '<Get>b__3'
10:06:34.633 10,211 Socket was reset. 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:34.633 10,209 Acquiring stream from pool. 10.100.240.129:11211
10:06:34.633 10,210 Socket 5315212e-7192-4d7e-91c4-f1d8497898b6 was reset
10:06:07.643 10,204 Action '<Get>b__3' executed. Took 10.0007 ms.
10:06:07.640 10,200 Action '<Get>b__3' executed. Took 6.9974 ms.
10:06:07.640 10,198 Action '<Get>b__3' executed. Took 6.9974 ms.
10:06:07.638 10,197 Are we alive? True
10:06:07.638 10,196 Releasing socket 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:07.637 10,192 Releasing socket 25294822-c500-493c-a4d2-b3362ceeb76c
10:06:07.637 10,193 Are we alive? True
10:06:07.637 10,194 Releasing socket 3b89141e-0895-4f1c-b5e0-454c291532c5
10:06:07.637 10,195 Are we alive? True
10:06:07.634 10,191 Socket was reset. 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:07.634 10,189 Socket 5315212e-7192-4d7e-91c4-f1d8497898b6 was reset
10:06:07.634 10,190 Socket was reset. 3b89141e-0895-4f1c-b5e0-454c291532c5
10:06:07.633 10,185 Executing action '<Get>b__3'
10:06:07.633 10,180 Acquiring stream from pool. 10.100.240.129:11211
10:06:07.633 10,182 Action '<Get>b__3' executed. Took 2997.032 ms.
10:06:07.633 10,183 Socket was reset. 25294822-c500-493c-a4d2-b3362ceeb76c
10:06:07.633 10,184 Executing action '<Get>b__3'
10:06:07.633 10,181 Socket 25294822-c500-493c-a4d2-b3362ceeb76c was reset
10:06:07.633 10,186 Acquiring stream from pool. 10.100.240.129:11211
10:06:07.633 10,187 Acquiring stream from pool. 10.100.240.129:11211
10:06:07.633 10,188 Socket 3b89141e-0895-4f1c-b5e0-454c291532c5 was reset
10:06:07.633 10,177 Action '<Get>b__3' executed. Took 3011.0364 ms.
10:06:07.633 10,178 Executing action '<Get>b__3'
10:06:07.632 10,172 Releasing socket 3b89141e-0895-4f1c-b5e0-454c291532c5
10:06:07.632 10,173 Are we alive? True
10:06:07.632 10,171 Releasing socket 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:07.632 10,175 Are we alive? True
10:06:07.632 10,176 Action '<Get>b__3' executed. Took 3015.0355 ms.
10:06:07.632 10,179 Are we alive? True
10:06:07.632 10,174 Releasing socket 25294822-c500-493c-a4d2-b3362ceeb76c
10:06:07.631 10,166 Socket 25294822-c500-493c-a4d2-b3362ceeb76c was reset
10:06:07.631 10,168 Socket was reset. 25294822-c500-493c-a4d2-b3362ceeb76c
10:06:07.631 10,169 Socket 3b89141e-0895-4f1c-b5e0-454c291532c5 was reset
10:06:07.631 10,170 Socket was reset. 3b89141e-0895-4f1c-b5e0-454c291532c5
10:06:07.631 10,167 Socket was reset. 5315212e-7192-4d7e-91c4-f1d8497898b6
10:06:07.630 10,162 Acquiring stream from pool. 10.100.240.129:11211
10:06:07.630 10,164 Acquiring stream from pool. 10.100.240.129:11211
10:06:07.630 10,165 Socket 5315212e-7192-4d7e-91c4-f1d8497898b6 was reset
10:06:07.630 10,161 Pool has been inited for 10.100.240.129:11211 with 10 sockets
10:06:07.630 10,163 Acquiring stream from pool. 10.100.240.129:11211
10:06:04.636 10,160 Executing action '<Get>b__3'
10:06:04.622 10,158 Executing action '<Get>b__3'
10:06:04.617 10,156 Executing action '<Get>b__3'
10:05:48.040 10,153 Are we alive? True
10:05:48.040 10,154 Are we alive? True
10:05:48.040 10,152 Releasing socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249
10:05:48.039 10,144 ReadLine: CONFIG cluster 0 78
10:05:48.039 10,145 Received response: CONFIG cluster 0 78
10:05:48.039 10,146 Received response: CONFIG cluster 0 78
10:05:48.039 10,147 ReadLine: END
10:05:48.039 10,148 ReadLine: END
10:05:48.039 10,149 Received response: END
10:05:48.039 10,150 Received response: END
10:05:48.039 10,151 Releasing socket 029d7806-e6ee-4dff-a62e-7a788d65b902
10:05:48.039 10,143 ReadLine: CONFIG cluster 0 78
10:05:48.037 10,135 Polling...
10:05:48.037 10,136 Polling...
10:05:48.037 10,137 Acquiring stream from pool. 10.100.240.129:11211
10:05:48.037 10,138 Acquiring stream from pool. 10.100.240.129:11211
10:05:48.037 10,139 Socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249 was reset
10:05:48.037 10,140 Socket 029d7806-e6ee-4dff-a62e-7a788d65b902 was reset
10:05:48.037 10,141 Socket was reset. a81d77c0-da1c-4cfd-830f-bde3a6fcf249
10:05:48.037 10,142 Socket was reset. 029d7806-e6ee-4dff-a62e-7a788d65b902
10:05:39.506 10,128 ReadLine: CONFIG cluster 0 78
10:05:39.506 10,129 Received response: CONFIG cluster 0 78
10:05:39.506 10,131 Received response: END
10:05:39.506 10,132 Releasing socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
10:05:39.506 10,133 Are we alive? True
10:05:39.506 10,134 Updating endpoints to have 1 nodes
10:05:39.506 10,130 ReadLine: END
10:05:39.504 10,125 Acquiring stream from pool. 10.100.240.129:11211
10:05:39.504 10,127 Socket was reset. 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
10:05:39.504 10,124 Polling...
10:05:39.504 10,126 Socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9 was reset
10:05:34.615 10,119 Executing action '<Get>b__3'
10:05:34.615 10,120 Action '<Get>b__3' executed. Took 0 ms.
10:05:34.605 10,114 Action '<Get>b__3' executed. Took 0 ms.
10:05:34.605 10,113 Executing action '<Get>b__3'
10:05:34.590 10,108 Action '<Get>b__3' executed. Took 0 ms.
10:05:34.590 10,107 Executing action '<Get>b__3'
10:05:04.592 10,102 Action '<Get>b__3' executed. Took 0 ms.
10:05:04.592 10,101 Executing action '<Get>b__3'
10:05:04.588 10,095 Executing action '<Get>b__3'
10:05:04.588 10,096 Action '<Get>b__3' executed. Took 0 ms.
10:05:04.572 10,089 Executing action '<Get>b__3'
10:05:04.572 10,090 Action '<Get>b__3' executed. Took 0 ms.
10:04:55.112 10,086 Checking the dead servers.
10:04:55.112 10,087 deadCount == 0, stopping the timer.
10:04:48.036 10,074 ReadLine: CONFIG cluster 0 78
10:04:48.036 10,075 ReadLine: CONFIG cluster 0 78
10:04:48.036 10,076 Received response: CONFIG cluster 0 78
10:04:48.036 10,077 Received response: CONFIG cluster 0 78
10:04:48.036 10,078 ReadLine: END
10:04:48.036 10,079 ReadLine: END
10:04:48.036 10,080 Received response: END
10:04:48.036 10,081 Received response: END
10:04:48.036 10,082 Releasing socket 029d7806-e6ee-4dff-a62e-7a788d65b902
10:04:48.036 10,083 Releasing socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249
10:04:48.036 10,084 Are we alive? True
10:04:48.036 10,085 Are we alive? True
10:04:48.035 10,073 Socket was reset. a81d77c0-da1c-4cfd-830f-bde3a6fcf249
10:04:48.034 10,066 Polling...
10:04:48.034 10,068 Acquiring stream from pool. 10.100.240.129:11211
10:04:48.034 10,069 Acquiring stream from pool. 10.100.240.129:11211
10:04:48.034 10,070 Socket 029d7806-e6ee-4dff-a62e-7a788d65b902 was reset
10:04:48.034 10,071 Socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249 was reset
10:04:48.034 10,072 Socket was reset. 029d7806-e6ee-4dff-a62e-7a788d65b902
10:04:48.034 10,067 Polling...
10:04:45.103 10,062 Action '<Get>b__3' executed. Took 10535.2048 ms.
10:04:45.102 10,060 Starting the recovery timer.
10:04:45.102 10,061 Timer started.
10:04:45.101 10,059 Node 10.100.240.129:11211 is dead.
10:04:45.099 10,058 Marking node 10.100.240.129:11211 as dead
10:04:45.098 10,056 Mark as dead was requested for 10.100.240.129:11211
10:04:45.098 10,057 FailurePolicy.ShouldFail(): True
10:04:45.097 10,054 Releasing socket bfdea8bc-4d7f-44c6-bc5a-67fc59485767
10:04:45.097 10,055 Are we alive? True
10:04:45.096 10,053 System.IO.IOException: Failed to read from the socket '10.100.240.129:11211'. Error: TimedOut
at Enyim.Caching.Memcached.PooledSocket.BasicNetworkStream.Read(Byte[] buffer, Int32 offset, Int32 count) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\BasicNetworkStream.cs:line 92
at System.IO.BufferedStream.Read(Byte[] array, Int32 offset, Int32 count)
at Enyim.Caching.Memcached.PooledSocket.Read(Byte[] buffer, Int32 offset, Int32 count) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\PooledSocket.cs:line 222
at Enyim.Caching.Memcached.Protocol.Binary.BinaryResponse.Read(PooledSocket socket) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\Protocol\Binary\BinaryResponse.cs:line 61
at Enyim.Caching.Memcached.Protocol.Binary.BinarySingleItemOperation.ReadResponse(PooledSocket socket) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\Protocol\Binary\BinarySingleItemOperation.cs:line 24
at Enyim.Caching.Memcached.MemcachedNode.ExecuteOperation(IOperation op) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\MemcachedNode.cs:line 525
10:04:39.491 10,048 Received response: CONFIG cluster 0 78
10:04:39.491 10,049 ReadLine: END
10:04:39.491 10,050 Received response: END
10:04:39.491 10,051 Releasing socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
10:04:39.491 10,052 Are we alive? True
10:04:39.491 10,047 ReadLine: CONFIG cluster 0 78
10:04:39.489 10,043 Polling...
10:04:39.489 10,044 Acquiring stream from pool. 10.100.240.129:11211
10:04:39.489 10,045 Socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9 was reset
10:04:39.489 10,046 Socket was reset. 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
10:04:34.576 10,038 Action '<Get>b__3' executed. Took 5.9978 ms.
10:04:34.575 10,037 Action '<Get>b__3' executed. Took 5.0007 ms.
10:04:34.574 10,036 Are we alive? True
И вот еще один случай:
Time messageId message
13:55:55.587 40,464 Action '<Get>b__3' executed. Took 8.9966 ms.
13:55:55.584 40,456 Action '<Get>b__3' executed. Took 6.9989 ms.
13:55:55.584 40,458 Action '<Get>b__3' executed. Took 5.9944 ms.
13:55:55.584 40,460 Are we alive? True
13:55:55.584 40,457 Releasing socket 71f372a3-37d3-4ecb-977d-c4f758b616a8
13:55:55.582 40,454 Releasing socket 62bdc6df-6920-457b-8679-eecdaeacb273
13:55:55.582 40,455 Are we alive? True
13:55:55.582 40,453 Are we alive? True
13:55:55.581 40,452 Releasing socket 09289917-8dc9-413b-9d16-2954eeb48382
13:55:55.579 40,451 Socket was reset. 71f372a3-37d3-4ecb-977d-c4f758b616a8
13:55:55.578 40,446 Socket 62bdc6df-6920-457b-8679-eecdaeacb273 was reset
13:55:55.578 40,443 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.578 40,444 Socket 09289917-8dc9-413b-9d16-2954eeb48382 was reset
13:55:55.578 40,440 Executing action '<Get>b__3'
13:55:55.578 40,441 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.578 40,447 Socket was reset. 09289917-8dc9-413b-9d16-2954eeb48382
13:55:55.578 40,448 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.578 40,449 Socket was reset. 62bdc6df-6920-457b-8679-eecdaeacb273
13:55:55.578 40,450 Socket 71f372a3-37d3-4ecb-977d-c4f758b616a8 was reset
13:55:55.578 40,442 Action '<Get>b__3' executed. Took 12177.9493 ms.
13:55:55.578 40,445 Executing action '<Get>b__3'
13:55:55.577 40,432 Releasing socket 62bdc6df-6920-457b-8679-eecdaeacb273
13:55:55.577 40,433 Are we alive? True
13:55:55.577 40,431 Releasing socket 71f372a3-37d3-4ecb-977d-c4f758b616a8
13:55:55.577 40,435 Action '<Get>b__3' executed. Took 11887.9703 ms.
13:55:55.577 40,436 Releasing socket 09289917-8dc9-413b-9d16-2954eeb48382
13:55:55.577 40,437 Action '<Get>b__3' executed. Took 12051.9306 ms.
13:55:55.577 40,438 Are we alive? True
13:55:55.577 40,439 Executing action '<Get>b__3'
13:55:55.577 40,434 Are we alive? True
13:55:55.576 40,427 Socket was reset. 62bdc6df-6920-457b-8679-eecdaeacb273
13:55:55.576 40,430 Socket was reset. 09289917-8dc9-413b-9d16-2954eeb48382
13:55:55.576 40,429 Socket 09289917-8dc9-413b-9d16-2954eeb48382 was reset
13:55:55.575 40,422 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.575 40,423 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.575 40,421 Pool has been inited for 10.100.240.129:11211 with 10 sockets
13:55:55.575 40,425 Socket 62bdc6df-6920-457b-8679-eecdaeacb273 was reset
13:55:55.575 40,426 Socket was reset. 71f372a3-37d3-4ecb-977d-c4f758b616a8
13:55:55.575 40,428 Acquiring stream from pool. 10.100.240.129:11211
13:55:55.575 40,424 Socket 71f372a3-37d3-4ecb-977d-c4f758b616a8 was reset
13:55:49.740 40,419 Are we alive? True
13:55:49.740 40,420 Are we alive? True
13:55:49.739 40,409 ReadLine: CONFIG cluster 0 78
13:55:49.739 40,410 ReadLine: CONFIG cluster 0 78
13:55:49.739 40,411 Received response: CONFIG cluster 0 78
13:55:49.739 40,412 Received response: CONFIG cluster 0 78
13:55:49.739 40,413 ReadLine: END
13:55:49.739 40,414 ReadLine: END
13:55:49.739 40,415 Received response: END
13:55:49.739 40,416 Received response: END
13:55:49.739 40,417 Releasing socket 029d7806-e6ee-4dff-a62e-7a788d65b902
13:55:49.739 40,418 Releasing socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249
13:55:49.738 40,407 Socket was reset. 029d7806-e6ee-4dff-a62e-7a788d65b902
13:55:49.738 40,408 Socket was reset. a81d77c0-da1c-4cfd-830f-bde3a6fcf249
13:55:49.737 40,402 Polling...
13:55:49.737 40,404 Acquiring stream from pool. 10.100.240.129:11211
13:55:49.737 40,405 Socket 029d7806-e6ee-4dff-a62e-7a788d65b902 was reset
13:55:49.737 40,406 Socket a81d77c0-da1c-4cfd-830f-bde3a6fcf249 was reset
13:55:49.737 40,401 Polling...
13:55:49.737 40,403 Acquiring stream from pool. 10.100.240.129:11211
13:55:43.689 40,400 Executing action '<Get>b__3'
13:55:43.525 40,398 Executing action '<Get>b__3'
13:55:43.400 40,396 Executing action '<Get>b__3'
13:55:41.332 40,389 Received response: CONFIG cluster 0 78
13:55:41.332 40,390 ReadLine: END
13:55:41.332 40,391 Received response: END
13:55:41.332 40,392 Releasing socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
13:55:41.332 40,393 Are we alive? True
13:55:41.332 40,394 Updating endpoints to have 1 nodes
13:55:41.332 40,388 ReadLine: CONFIG cluster 0 78
13:55:41.330 40,384 Polling...
13:55:41.330 40,385 Acquiring stream from pool. 10.100.240.129:11211
13:55:41.330 40,386 Socket 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9 was reset
13:55:41.330 40,387 Socket was reset. 798b0cd3-674d-4d7b-8c2e-2cfdbca28fe9
13:55:34.114 40,382 Checking the dead servers.
13:55:34.114 40,383 deadCount == 0, stopping the timer.
13:55:24.099 40,377 Timer started.
13:55:24.099 40,378 Action '<Get>b__3' executed. Took 10504.9201 ms.
13:55:24.098 40,371 Are we alive? True
13:55:24.098 40,372 Mark as dead was requested for 10.100.240.129:11211
13:55:24.098 40,373 FailurePolicy.ShouldFail(): True
13:55:24.098 40,374 Marking node 10.100.240.129:11211 as dead
13:55:24.098 40,375 Node 10.100.240.129:11211 is dead.
13:55:24.098 40,376 Starting the recovery timer.
13:55:24.097 40,369 System.IO.IOException: Failed to read from the socket '10.100.240.129:11211'. Error: TimedOut
at Enyim.Caching.Memcached.PooledSocket.BasicNetworkStream.Read(Byte[] buffer, Int32 offset, Int32 count) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\BasicNetworkStream.cs:line 92
at System.IO.BufferedStream.Read(Byte[] array, Int32 offset, Int32 count)
at Enyim.Caching.Memcached.PooledSocket.Read(Byte[] buffer, Int32 offset, Int32 count) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\PooledSocket.cs:line 222
at Enyim.Caching.Memcached.Protocol.Binary.BinaryResponse.Read(PooledSocket socket) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\Protocol\Binary\BinaryResponse.cs:line 61
at Enyim.Caching.Memcached.Protocol.Binary.BinarySingleItemOperation.ReadResponse(PooledSocket socket) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\Protocol\Binary\BinarySingleItemOperation.cs:line 24
at Enyim.Caching.Memcached.MemcachedNode.ExecuteOperation(IOperation op) in d:\Dropbox\Repo\EnyimMemcached\Enyim.Caching\Memcached\MemcachedNode.cs:line 525
13:55:24.097 40,370 Releasing socket 5b60d075-3c4f-4447-b71d-55c907eeba78
13:55:13.684 40,366 Action '<Get>b__3' executed. Took 4.9984 ms.
13:55:13.681 40,364 Releasing socket d344fce5-44f1-44a0-8781-d8c47b0fd150
13:55:13.681 40,365 Are we alive? True
13:55:13.679 40,359 Action '<Get>b__3' executed. Took 1.9999 ms.
13:55:13.679 40,360 Executing action '<Get>b__3'
13:55:13.679 40,361 Acquiring stream from pool. 10.100.240.129:11211
13:55:13.679 40,362 Socket d344fce5-44f1-44a0-8781-d8c47b0fd150 was reset
13:55:13.679 40,363 Socket was reset. d344fce5-44f1-44a0-8781-d8c47b0fd150
Обратите внимание, что некоторые сообщения журнала, имеющие одинаковую временную метку, могут быть не в порядке (поле messageId может использоваться для сортировки).