fix: Make sure ports are closed properly after the cleanup

[mykola-mokhnach]

Hopefully addresses appium/appium#13452

[mykola-mokhnach]

@KazuCocoa Could you please verify this PR works for you with real devices when you have time?

[KazuCocoa]

I tested this branch. I haven't reproduced the issue, so not sure the issue is fixed by this change.
But this change makes quit command slow almost 30 sec on may local.

• mjpeg server tests in ruby_lib_core worked as same as before 🆗
• quit took almost 30 sec (( 31.049107) is time by seconds) 🔥

  [5] pry(#<AppiumLibCoreTest::Ios::MjpegServerTest>)> require 'benchmark'
  => true
  [6] pry(#<AppiumLibCoreTest::Ios::MjpegServerTest>)> puts Benchmark.measure { @@driver.quit }
    # this branch
    0.000511   0.000224   0.000735 ( 31.049107)
  => nil
  [7] pry(#<AppiumLibCoreTest::Ios::MjpegServerTest>)> @@driver = @@core.start_driver
  => #<Appium::Core::Base::Driver:0x46f258e63be99b0a browser=:"">
  [8] pry(#<AppiumLibCoreTest::Ios::MjpegServerTest>)> puts Benchmark.measure { @@driver.quit }
    # current master
    0.000506   0.000193   0.000699 (  1.035375)
  => nil
  

[debug] [WD Proxy] }
[DevCon Factory] Releasing connections for 242bfcc998fd156df0bd0ad1dde8ab8e0a032114 device on any port number
[DevCon Factory] Found cached connections to release: ["242bfcc998fd156df0bd0ad1dde8ab8e0a032114:8100"]
[DevCon Factory] Releasing the listener for '242bfcc998fd156df0bd0ad1dde8ab8e0a032114:8100'
// Here took over 20 sec
[debug] [DevCon Factory] Cached connections count: 0
[debug] [XCUITest] Not clearing log files. Use `clearSystemFiles` capability to turn on.

[mykola-mokhnach]

Thanks for checking it @KazuCocoa
I did several fixes, does it look better now?

[KazuCocoa]

The result was 31.059937 sec. It took almost 30 sec before [iProxy@242bf...] The connection has been closed message.

[HTTP] --> DELETE /wd/hub/session/fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69
[HTTP] {}
[debug] [W3C (fd99a1fa)] Calling AppiumDriver.deleteSession() with args: ["fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69"]
[debug] [BaseDriver] Event 'quitSessionRequested' logged at 1572074360989 (16:19:20 GMT+0900 (Japan Standard Time))
[Appium] Removing session fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69 from our master session list
[debug] [WD Proxy] Matched '/session/fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69' to command name 'deleteSession'
[debug] [WD Proxy] Proxying [DELETE /session/fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69] to [DELETE http://localhost:8100/session/A0CCFBD2-C2E9-4A1D-92DA-145F46D37DA1] with no body
[debug] [WD Proxy] Got response with status 200: {
[debug] [WD Proxy]   "value" : null,
[debug] [WD Proxy]   "sessionId" : "F07ECEFF-5F58-4768-8E46-670CB78347DB"
[debug] [WD Proxy] }
[DevCon Factory] Releasing connections for 242bfcc998fd156df0bd0ad1dde8ab8e0a032114 device on any port number
[DevCon Factory] Found cached connections to release: ["242bfcc998fd156df0bd0ad1dde8ab8e0a032114:8100"]
[DevCon Factory] Releasing the listener for '242bfcc998fd156df0bd0ad1dde8ab8e0a032114:8100'
// took almost 30 sec here
[iProxy@242bf...] The connection has been closed
[debug] [DevCon Factory] Cached connections count: 0
[debug] [XCUITest] Not clearing log files. Use `clearSystemFiles` capability to turn on.
[debug] [BaseDriver] Event 'quitSessionFinished' logged at 1572074392046 (16:19:52 GMT+0900 (Japan Standard Time))
[debug] [W3C (fd99a1fa)] Received response: null
[debug] [W3C (fd99a1fa)] But deleting session, so not returning
[debug] [W3C (fd99a1fa)] Responding to client with driver.deleteSession() result: null
[HTTP] <-- DELETE /wd/hub/session/fd99a1fa-5ea5-4dfa-a4d4-237cc3df0b69 200 31058 ms - 14
[HTTP]

[mykola-mokhnach]

it looks like we are facing the problem similar to https://stackoverflow.com/questions/49268934/socket-in-close-wait-for-node-js-client

I'll add the necessary fixes to ios-device lib

[mykola-mokhnach]

Changes added in appium/appium-ios-device#53

[KazuCocoa]

I applied both ios-device and 2ba188a , but no luck... (The same result.)
But the point of end looks correct for me 👀 https://nodejs.org/api/net.html#net_socket_end_data_encoding_callback

[mykola-mokhnach]

@umutuzgur Do you have any more ideas on that?

[umutuzgur]

@mykola-mokhnach Maybe we need to wait for a close event when we call socket.end() in appium-ios-device to avoid any chance of a race condition?

[mykola-mokhnach]

Maybe we need to wait for a close event when we call socket.end() in appium-ios-device to avoid any chance of a race condition?

@umutuzgur I like such approach, although we need to carefully test this functionality first to make sure iOS handles partial socket closing properly. Otherwise there might be unexpected delays.

[KazuCocoa]

👍