warmcat / libwebsockets

canonical libwebsockets.org networking library
https://libwebsockets.org
Other
4.73k stars 1.48k forks source link

connection takes too much time #739

Closed huidi7 closed 7 years ago

huidi7 commented 7 years ago

Hi,

I wrote a test client, and found a problem on the websocket connection. It took more than 10 seconds to succeed the connection. Sometimes, it took even more than 60s. The server is a simple echo server deployed on another server.

The following is the log dumped with debug open. Could you please shed some lights on this?

The reason value is dumped on the callback.

[2017/01/05 09:44:17:1365] NOTICE: set lws log level to 511 [2017/01/05 09:44:17:1366] NOTICE: start to init client context. [2017/01/05 09:44:17:1367] NOTICE: Initial logging level 511 [2017/01/05 09:44:17:1368] NOTICE: Libwebsockets version: 2.1.0 huiding@huiding-VirtualBox-v2.0.0-209-gbe9fb91 [2017/01/05 09:44:17:1369] NOTICE: IPV6 not compiled in [2017/01/05 09:44:17:1370] NOTICE: libev support not compiled in [2017/01/05 09:44:17:1371] NOTICE: libuv support not compiled in [2017/01/05 09:44:17:1372] INFO: LWS_DEF_HEADER_LEN : 4096 [2017/01/05 09:44:17:1373] INFO: LWS_MAX_PROTOCOLS : 5 [2017/01/05 09:44:17:1374] INFO: LWS_MAX_SMP : 32 [2017/01/05 09:44:17:1375] INFO: SPEC_LATEST_SUPPORTED : 13 [2017/01/05 09:44:17:1375] INFO: sizeof (*info) : 192 [2017/01/05 09:44:17:1376] INFO: SYSTEM_RANDOM_FILEPATH: '/dev/urandom' [2017/01/05 09:44:17:1378] INFO: default timeout (secs): 20 [2017/01/05 09:44:17:1382] NOTICE: Threads: 1 each 1024 fds [2017/01/05 09:44:17:1383] INFO: mem: context: 6968 bytes (2872 ctx + (1 thr x 4096)) [2017/01/05 09:44:17:1384] INFO: mem: http hdr rsvd: 30736 bytes (1 thr x (4096 + 3588) x 4)) [2017/01/05 09:44:17:1386] INFO: mem: pollfd map: 8192 [2017/01/05 09:44:17:1388] NOTICE: mem: platform fd map: 4096 bytes [2017/01/05 09:44:17:1390] NOTICE: Creating Vhost 'default' port -1, 1 protocols, IPv6 off [2017/01/05 09:44:17:1391] NOTICE: mem: per-conn: 416 bytes + protocol rx buf [2017/01/05 09:44:17:1392] NOTICE: canonical_hostname = WiFiDemo_BFA8 [2017/01/05 09:44:17:1393] NOTICE: [Main] context created. [2017/01/05 09:44:17:1399] NOTICE: [Main] wsi create success. [2017/01/05 09:44:17:1400] NOTICE: Try to connect ws server [2017/01/05 09:44:17:1403] NOTICE: lws_protocol_init [2017/01/05 09:44:17:1404] NOTICE: >> reason: 27 [2017/01/05 09:44:17:1405] DEBUG: lws_union_transition: 0x470608: mode 32 [2017/01/05 09:44:17:1408] INFO: lws_header_table_attach: wsi 0x470608: ah (nil) (tsi 0, count = 0) in [2017/01/05 09:44:17:1409] INFO: lws_header_table_attach: wsi 0x470608: ah 0x469c50: count 1 (on exit) [2017/01/05 09:44:17:1410] CLIENT: lws_client_connect: direct conn [2017/01/05 09:44:17:1411] CLIENT: lws_client_connect_2 [2017/01/05 09:44:17:1412] CLIENT: lws_client_connect_2: address 121.199.1.200 [2017/01/05 09:44:27:3364] DEBUG: insert_wsi_socket_into_fds: 0x470608: tsi=0, sock=6, pos-in-fds=1 [2017/01/05 09:44:27:3366] NOTICE: >> reason: 35 [2017/01/05 09:44:27:3367] NOTICE: >> reason: 32 [2017/01/05 09:44:27:3368] NOTICE: >> reason: 36 [2017/01/05 09:44:27:3369] NOTICE: >> reason: 35 [2017/01/05 09:44:27:3370] NOTICE: >> reason: 34 [2017/01/05 09:44:27:3371] NOTICE: >> reason: 36 [2017/01/05 09:44:27:3371] NOTICE: >> reason: 29 [2017/01/05 09:44:27:3372] DEBUG: lws_set_timeout: 0x470608: 20 secs [2017/01/05 09:44:27:3377] CLIENT: nonblocking connect retry (errno = 150) [2017/01/05 09:44:27:3378] NOTICE: >> reason: 35 [2017/01/05 09:44:27:3379] NOTICE: >> reason: 34 [2017/01/05 09:44:27:3380] NOTICE: >> reason: 36 [2017/01/05 09:44:27:3381] NOTICE: >> reason: 31 [2017/01/05 09:44:27:3923] NOTICE: >> reason: 31 [2017/01/05 09:44:27:4482] NOTICE: >> reason: 31 [2017/01/05 09:44:27:5043] NOTICE: >> reason: 31 [2017/01/05 09:44:27:5602] NOTICE: >> reason: 31 [2017/01/05 09:44:27:6163] NOTICE: >> reason: 31 [2017/01/05 09:44:27:6722] NOTICE: >> reason: 31 [2017/01/05 09:44:27:7283] NOTICE: >> reason: 31 [2017/01/05 09:44:27:7842] NOTICE: >> reason: 31 [2017/01/05 09:44:27:8403] NOTICE: >> reason: 31 [2017/01/05 09:44:27:8963] NOTICE: >> reason: 31 [2017/01/05 09:44:27:9522] NOTICE: >> reason: 31 [2017/01/05 09:44:28:0083] NOTICE: >> reason: 31 [2017/01/05 09:44:28:0642] NOTICE: >> reason: 31 [2017/01/05 09:44:28:1203] NOTICE: >> reason: 31 [2017/01/05 09:44:28:1762] NOTICE: >> reason: 31 [2017/01/05 09:44:28:2323] NOTICE: >> reason: 31 [2017/01/05 09:44:28:2883] NOTICE: >> reason: 31 [2017/01/05 09:44:28:3442] NOTICE: >> reason: 31 [2017/01/05 09:44:28:4002] NOTICE: >> reason: 31 [2017/01/05 09:44:28:4562] NOTICE: >> reason: 31 [2017/01/05 09:44:28:5123] NOTICE: >> reason: 31 [2017/01/05 09:44:28:5682] NOTICE: >> reason: 31 [2017/01/05 09:44:28:6243] NOTICE: >> reason: 31 [2017/01/05 09:44:28:6802] NOTICE: >> reason: 31 [2017/01/05 09:44:28:7363] NOTICE: >> reason: 31 [2017/01/05 09:44:28:7922] NOTICE: >> reason: 31 [2017/01/05 09:44:28:8483] NOTICE: >> reason: 31 [2017/01/05 09:44:28:9042] NOTICE: >> reason: 31 [2017/01/05 09:44:28:9603] NOTICE: >> reason: 31 [2017/01/05 09:44:29:0162] NOTICE: >> reason: 31 [2017/01/05 09:44:29:0723] NOTICE: >> reason: 31 [2017/01/05 09:44:29:1283] NOTICE: >> reason: 31 [2017/01/05 09:44:29:1843] NOTICE: >> reason: 31 [2017/01/05 09:44:29:2403] NOTICE: >> reason: 31 [2017/01/05 09:44:29:2962] NOTICE: >> reason: 31 [2017/01/05 09:44:29:3523] NOTICE: >> reason: 31 [2017/01/05 09:44:29:4082] NOTICE: >> reason: 31 [2017/01/05 09:44:29:4643] NOTICE: >> reason: 31 [2017/01/05 09:44:29:5202] NOTICE: >> reason: 31 [2017/01/05 09:44:29:5762] NOTICE: >> reason: 31 [2017/01/05 09:44:29:6322] NOTICE: >> reason: 31 [2017/01/05 09:44:29:6884] NOTICE: >> reason: 31 [2017/01/05 09:44:29:7443] NOTICE: >> reason: 31 [2017/01/05 09:44:29:8003] NOTICE: >> reason: 31 [2017/01/05 09:44:29:8562] NOTICE: >> reason: 31 [2017/01/05 09:44:29:9122] NOTICE: >> reason: 31 [2017/01/05 09:44:29:9683] NOTICE: >> reason: 31 [2017/01/05 09:44:30:0242] NOTICE: >> reason: 31 [2017/01/05 09:44:30:0803] NOTICE: >> reason: 31 [2017/01/05 09:44:30:1362] NOTICE: >> reason: 31 [2017/01/05 09:44:30:1923] NOTICE: >> reason: 31 [2017/01/05 09:44:30:2482] NOTICE: >> reason: 31 [2017/01/05 09:44:30:3042] NOTICE: >> reason: 31 [2017/01/05 09:44:30:3603] NOTICE: >> reason: 31 [2017/01/05 09:44:30:4162] NOTICE: >> reason: 31 [2017/01/05 09:44:30:4722] NOTICE: >> reason: 31 [2017/01/05 09:44:30:5282] NOTICE: >> reason: 31 [2017/01/05 09:44:30:5345] DEBUG: fd=6, revents=4 [2017/01/05 09:44:30:5346] NOTICE: >> reason: 35 [2017/01/05 09:44:30:5347] NOTICE: >> reason: 34 [2017/01/05 09:44:30:5348] NOTICE: >> reason: 36 [2017/01/05 09:44:30:5349] CLIENT: lws_client_connect_2 [2017/01/05 09:44:30:5350] CLIENT: lws_client_connect_2: address 121.199.1.200 [2017/01/05 09:44:55:6003] CLIENT: connected [2017/01/05 09:44:55:6005] DEBUG: lws_set_timeout: 0x470608: 20 secs [2017/01/05 09:44:55:6006] DEBUG: fd=6, revents=1 [2017/01/05 09:44:55:6007] NOTICE: >> reason: 35 [2017/01/05 09:44:55:6008] NOTICE: >> reason: 34 [2017/01/05 09:44:55:6009] NOTICE: >> reason: 36 [2017/01/05 09:44:55:6010] DEBUG: lws_set_timeout: 0x470608: 20 secs [2017/01/05 09:44:55:6013] NOTICE: >> reason: 24 [2017/01/05 09:44:55:6017] DEBUG: lws_set_timeout: 0x470608: 20 secs [2017/01/05 09:44:55:6018] NOTICE: >> reason: 31 [2017/01/05 09:44:55:6562] NOTICE: >> reason: 31 [2017/01/05 09:44:55:7123] NOTICE: >> reason: 31 [2017/01/05 09:44:55:7683] NOTICE: >> reason: 31 [2017/01/05 09:44:55:8242] NOTICE: >> reason: 31 [2017/01/05 09:44:55:8316] DEBUG: fd=6, revents=1 [2017/01/05 09:44:55:8317] PARSER: WSI_TOKEN_NAME_PART 'H' (mode=40) [2017/01/05 09:44:55:8318] PARSER: WSI_TOKEN_NAME_PART 'T' (mode=40) [2017/01/05 09:44:55:8319] PARSER: WSI_TOKEN_NAME_PART 'T' (mode=40) [2017/01/05 09:44:55:8320] PARSER: WSI_TOKEN_NAME_PART 'P' (mode=40) [2017/01/05 09:44:55:8321] PARSER: WSI_TOKEN_NAME_PART '/' (mode=40) [2017/01/05 09:44:55:8323] PARSER: WSI_TOKEN_NAME_PART '1' (mode=40) [2017/01/05 09:44:55:8324] PARSER: WSI_TOKEN_NAME_PART '.' (mode=40) [2017/01/05 09:44:55:8325] PARSER: WSI_TOKEN_NAME_PART '1' (mode=40) [2017/01/05 09:44:55:8326] PARSER: WSI_TOKEN_NAME_PART ' ' (mode=40) [2017/01/05 09:44:55:8327] PARSER: known hdr 15 [2017/01/05 09:44:55:8328] PARSER: WSITOK(15) '1' [2017/01/05 09:44:55:8329] PARSER: WSITOK(15) '0' [2017/01/05 09:44:55:8330] PARSER: WSITOK(15) '1' [2017/01/05 09:44:55:8331] PARSER: WSITOK(15) ' ' [2017/01/05 09:44:55:8332] PARSER: WSITOK(15) 'S' [2017/01/05 09:44:55:8333] PARSER: WSITOK(15) 'w' [2017/01/05 09:44:55:8334] PARSER: WSITOK(15) 'i' [2017/01/05 09:44:55:8335] PARSER: WSITOK(15) 't' [2017/01/05 09:44:55:8336] PARSER: WSITOK(15) 'c' [2017/01/05 09:44:55:8337] PARSER: WSITOK(15) 'h' [2017/01/05 09:44:55:8338] PARSER: WSITOK(15) 'i' [2017/01/05 09:44:55:8339] PARSER: WSITOK(15) 'n' [2017/01/05 09:44:55:8340] PARSER: WSITOK(15) 'g' [2017/01/05 09:44:55:8341] PARSER: WSITOK(15) ' ' [2017/01/05 09:44:55:8342] PARSER: WSITOK(15) 'P' [2017/01/05 09:44:55:8343] PARSER: WSITOK(15) 'r' [2017/01/05 09:44:55:8344] PARSER: WSITOK(15) 'o' [2017/01/05 09:44:55:8345] PARSER: WSITOK(15) 't' [2017/01/05 09:44:55:8346] PARSER: WSITOK(15) 'o' [2017/01/05 09:44:55:8347] PARSER: WSITOK(15) 'c' [2017/01/05 09:44:55:8348] PARSER: WSITOK(15) 'o' [2017/01/05 09:44:55:8349] PARSER: WSITOK(15) 'l' [2017/01/05 09:44:55:8350] PARSER: WSITOK(15) 's' '2017/01/05 09:44:55:8351] PARSER: WSITOK(15) ' [2017/01/05 09:44:55:8352] PARSER: [2017/01/05 09:44:55:8353] PARSER: WSI_TOKEN_SKIPPING_SAW_CR ' ' [2017/01/05 09:44:55:8354] PARSER: WSI_TOKEN_NAME_PART 'D' (mode=40) [2017/01/05 09:44:55:8355] PARSER: WSI_TOKEN_NAME_PART 'a' (mode=40) [2017/01/05 09:44:55:8356] PARSER: WSI_TOKEN_NAME_PART 't' (mode=40) [2017/01/05 09:44:55:8357] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:55:8358] PARSER: WSI_TOKEN_NAME_PART ':' (mode=40) [2017/01/05 09:44:55:8359] PARSER: known hdr 29 [2017/01/05 09:44:55:8360] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8361] PARSER: WSITOK(29) 'T' [2017/01/05 09:44:55:8362] PARSER: WSITOK(29) 'h' [2017/01/05 09:44:55:8363] PARSER: WSITOK(29) 'u' [2017/01/05 09:44:55:8364] PARSER: WSITOK(29) ',' [2017/01/05 09:44:55:8365] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8366] PARSER: WSITOK(29) '0' [2017/01/05 09:44:55:8367] PARSER: WSITOK(29) '5' [2017/01/05 09:44:55:8368] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8369] PARSER: WSITOK(29) 'J' [2017/01/05 09:44:55:8370] PARSER: WSITOK(29) 'a' [2017/01/05 09:44:55:8371] PARSER: WSITOK(29) 'n' [2017/01/05 09:44:55:8372] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8373] PARSER: WSITOK(29) '2' [2017/01/05 09:44:55:8374] PARSER: WSITOK(29) '0' [2017/01/05 09:44:55:8375] PARSER: WSITOK(29) '1' [2017/01/05 09:44:55:8376] PARSER: WSITOK(29) '7' [2017/01/05 09:44:55:8377] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8378] PARSER: WSITOK(29) '0' [2017/01/05 09:44:55:8379] PARSER: WSITOK(29) '9' [2017/01/05 09:44:55:8380] PARSER: WSITOK(29) ':' [2017/01/05 09:44:55:8381] PARSER: WSITOK(29) '4' [2017/01/05 09:44:55:8382] PARSER: WSITOK(29) '4' [2017/01/05 09:44:55:8383] PARSER: WSITOK(29) ':' [2017/01/05 09:44:55:8384] PARSER: WSITOK(29) '5' [2017/01/05 09:44:55:8385] PARSER: WSITOK(29) '5' [2017/01/05 09:44:55:8386] PARSER: WSITOK(29) ' ' [2017/01/05 09:44:55:8387] PARSER: WSITOK(29) 'G' [2017/01/05 09:44:55:8388] PARSER: WSITOK(29) 'M' [2017/01/05 09:44:55:8389] PARSER: WSITOK(29) 'T' '2017/01/05 09:44:55:8390] PARSER: WSITOK(29) ' [2017/01/05 09:44:56:4985] PARSER: [2017/01/05 09:44:56:4987] PARSER: WSI_TOKEN_SKIPPING_SAW_CR ' ' [2017/01/05 09:44:56:4988] PARSER: WSI_TOKEN_NAME_PART 'C' (mode=40) [2017/01/05 09:44:56:4989] PARSER: WSI_TOKEN_NAME_PART 'o' (mode=40) [2017/01/05 09:44:56:4990] PARSER: WSI_TOKEN_NAME_PART 'n' (mode=40) [2017/01/05 09:44:56:4991] PARSER: WSI_TOKEN_NAME_PART 'n' (mode=40) [2017/01/05 09:44:56:4991] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:56:4992] PARSER: WSI_TOKEN_NAME_PART 'c' (mode=40) [2017/01/05 09:44:56:4993] PARSER: WSI_TOKEN_NAME_PART 't' (mode=40) [2017/01/05 09:44:56:4994] PARSER: WSI_TOKEN_NAME_PART 'i' (mode=40) [2017/01/05 09:44:56:4995] PARSER: WSI_TOKEN_NAME_PART 'o' (mode=40) [2017/01/05 09:44:56:4996] PARSER: WSI_TOKEN_NAME_PART 'n' (mode=40) [2017/01/05 09:44:56:4997] PARSER: WSI_TOKEN_NAME_PART ':' (mode=40) [2017/01/05 09:44:56:4998] PARSER: known hdr 4 [2017/01/05 09:44:56:4999] PARSER: WSITOK(4) ' ' [2017/01/05 09:44:56:5000] PARSER: WSITOK(4) 'U' [2017/01/05 09:44:56:5001] PARSER: WSITOK(4) 'p' [2017/01/05 09:44:56:5003] PARSER: WSITOK(4) 'g' [2017/01/05 09:44:56:5003] PARSER: WSITOK(4) 'r' [2017/01/05 09:44:56:5004] PARSER: WSITOK(4) 'a' [2017/01/05 09:44:56:5005] PARSER: WSITOK(4) 'd' [2017/01/05 09:44:56:5006] PARSER: WSITOK(4) 'e' '2017/01/05 09:44:56:5007] PARSER: WSITOK(4) ' [2017/01/05 09:44:56:5008] PARSER: [2017/01/05 09:44:56:5009] PARSER: WSI_TOKEN_SKIPPING_SAW_CR ' ' [2017/01/05 09:44:56:5010] PARSER: WSI_TOKEN_NAME_PART 'S' (mode=40) [2017/01/05 09:44:56:5011] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:56:5012] PARSER: WSI_TOKEN_NAME_PART 'c' (mode=40) [2017/01/05 09:44:56:5013] PARSER: WSI_TOKEN_NAME_PART '-' (mode=40) [2017/01/05 09:44:56:5014] PARSER: WSI_TOKEN_NAME_PART 'W' (mode=40) [2017/01/05 09:44:56:5015] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:56:5016] PARSER: WSI_TOKEN_NAME_PART 'b' (mode=40) [2017/01/05 09:44:56:5017] PARSER: WSI_TOKEN_NAME_PART 'S' (mode=40) [2017/01/05 09:44:56:5018] PARSER: WSI_TOKEN_NAME_PART 'o' (mode=40) [2017/01/05 09:44:56:5019] PARSER: WSI_TOKEN_NAME_PART 'c' (mode=40) [2017/01/05 09:44:56:5020] PARSER: WSI_TOKEN_NAME_PART 'k' (mode=40) [2017/01/05 09:44:56:5021] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:56:5022] PARSER: WSI_TOKEN_NAME_PART 't' (mode=40) [2017/01/05 09:44:56:5023] PARSER: WSI_TOKEN_NAME_PART '-' (mode=40) [2017/01/05 09:44:56:5024] PARSER: WSI_TOKEN_NAME_PART 'A' (mode=40) [2017/01/05 09:44:56:5025] PARSER: WSI_TOKEN_NAME_PART 'c' (mode=40) [2017/01/05 09:44:56:5026] PARSER: WSI_TOKEN_NAME_PART 'c' (mode=40) [2017/01/05 09:44:56:5027] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:56:5028] PARSER: WSI_TOKEN_NAME_PART 'p' (mode=40) [2017/01/05 09:44:56:5029] PARSER: WSI_TOKEN_NAME_PART 't' (mode=40) [2017/01/05 09:44:56:5030] PARSER: WSI_TOKEN_NAME_PART ':' (mode=40) [2017/01/05 09:44:56:5031] PARSER: known hdr 13 [2017/01/05 09:44:56:5032] PARSER: WSITOK(13) ' ' [2017/01/05 09:44:56:5033] PARSER: WSITOK(13) 'p' [2017/01/05 09:44:56:5034] PARSER: WSITOK(13) 'M' [2017/01/05 09:44:56:5035] PARSER: WSITOK(13) 'R' [2017/01/05 09:44:56:5036] PARSER: WSITOK(13) 'q' [2017/01/05 09:44:56:5037] PARSER: WSITOK(13) 'w' [2017/01/05 09:44:56:5038] PARSER: WSITOK(13) 'b' [2017/01/05 09:44:56:5039] PARSER: WSITOK(13) 'O' [2017/01/05 09:44:56:5040] PARSER: WSITOK(13) 'l' [2017/01/05 09:44:56:5041] PARSER: WSITOK(13) '5' [2017/01/05 09:44:56:5042] PARSER: WSITOK(13) 'd' [2017/01/05 09:44:56:5043] PARSER: WSITOK(13) 'r' [2017/01/05 09:44:56:5044] PARSER: WSITOK(13) 'b' [2017/01/05 09:44:56:5045] PARSER: WSITOK(13) 'f' [2017/01/05 09:44:56:5046] PARSER: WSITOK(13) '3' [2017/01/05 09:44:56:5047] PARSER: WSITOK(13) 'c' [2017/01/05 09:44:56:5048] PARSER: WSITOK(13) '4' [2017/01/05 09:44:57:1646] PARSER: WSITOK(13) 'e' [2017/01/05 09:44:57:1647] PARSER: WSITOK(13) 'z' [2017/01/05 09:44:57:1648] PARSER: WSITOK(13) 'A' [2017/01/05 09:44:57:1649] PARSER: WSITOK(13) '7' [2017/01/05 09:44:57:1650] PARSER: WSITOK(13) 'K' [2017/01/05 09:44:57:1651] PARSER: WSITOK(13) 'h' [2017/01/05 09:44:57:1652] PARSER: WSITOK(13) 'k' [2017/01/05 09:44:57:1653] PARSER: WSITOK(13) '2' [2017/01/05 09:44:57:1654] PARSER: WSITOK(13) 'n' [2017/01/05 09:44:57:1655] PARSER: WSITOK(13) 'x' [2017/01/05 09:44:57:1655] PARSER: WSITOK(13) 's' [2017/01/05 09:44:57:1656] PARSER: WSITOK(13) '=' '2017/01/05 09:44:57:1657] PARSER: WSITOK(13) ' [2017/01/05 09:44:57:1658] PARSER: [2017/01/05 09:44:57:1659] PARSER: WSI_TOKEN_SKIPPING_SAW_CR ' ' [2017/01/05 09:44:57:1660] PARSER: WSI_TOKEN_NAME_PART 'U' (mode=40) [2017/01/05 09:44:57:1661] PARSER: WSI_TOKEN_NAME_PART 'p' (mode=40) [2017/01/05 09:44:57:1662] PARSER: WSI_TOKEN_NAME_PART 'g' (mode=40) [2017/01/05 09:44:57:1663] PARSER: WSI_TOKEN_NAME_PART 'r' (mode=40) [2017/01/05 09:44:57:1664] PARSER: WSI_TOKEN_NAME_PART 'a' (mode=40) [2017/01/05 09:44:57:1665] PARSER: WSI_TOKEN_NAME_PART 'd' (mode=40) [2017/01/05 09:44:57:1666] PARSER: WSI_TOKEN_NAME_PART 'e' (mode=40) [2017/01/05 09:44:57:1667] PARSER: WSI_TOKEN_NAME_PART ':' (mode=40) [2017/01/05 09:44:57:1668] PARSER: known hdr 5 [2017/01/05 09:44:57:1669] PARSER: WSITOK(5) ' ' [2017/01/05 09:44:57:1670] PARSER: WSITOK(5) 'W' [2017/01/05 09:44:57:1671] PARSER: WSITOK(5) 'e' [2017/01/05 09:44:57:1672] PARSER: WSITOK(5) 'b' [2017/01/05 09:44:57:1673] PARSER: WSITOK(5) 'S' [2017/01/05 09:44:57:1674] PARSER: WSITOK(5) 'o' [2017/01/05 09:44:57:1675] PARSER: WSITOK(5) 'c' [2017/01/05 09:44:57:1676] PARSER: WSITOK(5) 'k' [2017/01/05 09:44:57:1677] PARSER: WSITOK(5) 'e' [2017/01/05 09:44:57:1678] PARSER: WSITOK(5) 't' '2017/01/05 09:44:57:1679] PARSER: WSITOK(5) ' [2017/01/05 09:44:57:1680] PARSER: * [2017/01/05 09:44:57:1680] PARSER: WSI_TOKEN_SKIPPING_SAW_CR ' ' ' (mode=40) 09:44:57:1681] PARSER: WSI_TOKEN_NAME_PART ' [2017/01/05 09:44:57:1685] PARSER: WSI_TOKEN_NAME_PART ' ' (mode=40) [2017/01/05 09:44:57:1686] PARSER: known hdr 8 [2017/01/05 09:44:57:1687] PARSER: v13 hdrs completed [2017/01/05 09:44:57:1688] PARSER: lws_client_int_s_hs: no protocol list [2017/01/05 09:44:57:1689] INFO: lws_client_int_s_hs: WSI_TOKEN_PROTOCOL is null [2017/01/05 09:44:57:1690] INFO: lws_ensure_user_space: 0x470608 protocol 0x7f9ec928 [2017/01/05 09:44:57:1691] INFO: lws_ensure_user_space: 0x470608 protocol pss 0, user_space=0 [2017/01/05 09:44:57:1692] NOTICE: >> reason: 2 [2017/01/05 09:44:57:1693] DEBUG: lws_set_timeout: 0x470608: 0 secs [2017/01/05 09:44:57:1694] INFO: lws_header_table_detach: wsi 0x470608: ah 0x469c50 (tsi=0, count = 1) [2017/01/05 09:44:57:1695] NOTICE: lws_header_table_detach: wsi 0x470608: ah held 40s, ah.rxpos 0, ah.rxlen 0, mode/state 40 7,wsi->more_rx_waiting 0 [2017/01/05 09:44:57:1696] INFO: lws_header_table_detach: wsi 0x470608: ah 0x469c50 (tsi=0, count = 0) [2017/01/05 09:44:57:1697] DEBUG: lws_union_transition: 0x470608: mode 4 [2017/01/05 09:44:57:1698] INFO: Allocating client RX buffer 4112 [2017/01/05 09:44:57:1699] DEBUG: handshake OK for protocol [2017/01/05 09:44:57:1700] NOTICE: [Main Service] Connect with server success.

lws-team commented 7 years ago
[2017/01/05 09:44:30:5350] CLIENT: lws_client_connect_2: address 121.199.1.200
[2017/01/05 09:44:55:6003] CLIENT: connected

This kind of issue is often related to DNS arrangements. Or, maybe the server there took 25s to accept your connection.

It's pretty much 25s... there is nothing in lws that waits like that (unless you set the general timeout to 25s in your code)

Whatever way I look at it, it sounds like the something external to lws decided to take 25s.

huidi7 commented 7 years ago

Andy,

Thanks for your quick reply.

There is no such issue when running client locally on the same server with echo server. And I bypassed the dns concern by using IP and port directly in uri.

Besides the 25s delay, it's really strange that it took 10s before callback invoked during connection. Could this be caused by network issue?

[2017/01/05 09:44:17:1405] DEBUG: lws_union_transition: 0x470608: mode 32 [2017/01/05 09:44:17:1408] INFO: lws_header_table_attach: wsi 0x470608: ah (nil) (tsi 0, count = 0) in [2017/01/05 09:44:17:1409] INFO: lws_header_table_attach: wsi 0x470608: ah 0x469c50: count 1 (on exit) [2017/01/05 09:44:17:1410] CLIENT: lws_client_connect: direct conn [2017/01/05 09:44:17:1411] CLIENT: lws_client_connect_2 [2017/01/05 09:44:17:1412] CLIENT: lws_client_connect_2: address 121.199.1.200 [2017/01/05 09:44:27:3364] DEBUG: insert_wsi_socket_into_fds: 0x470608: tsi=0, sock=6, pos-in-fds=1 [2017/01/05 09:44:27:3366] NOTICE: >> reason: 35

lws-team commented 7 years ago

By "DNS" I mean it may be doing rnds.

Hm dunno... Are you by any chance on the High Gravity planet from the movie Interstellar?

10s.... 25s... they are all kind of round numbers so far.

Can this problem be found if you visit a different server?

lws-team commented 7 years ago

There's nothing for me to do about this... closing.

huidi7 commented 7 years ago

It was caused by the address resolution in getaddrinfo during client handshake.

DonXiAn commented 5 years ago

It was caused by the address resolution in getaddrinfo during client handshake.

why address resolution can cause this problem. I meet similar problem(my service has 2 instances which is deployed in 2 vms, one vm has problem ,the other no problem). problem vm tcpdump result has gateway. no problem vm tcp dump is ip address not gateway. IP mmlservice-84c994bbfd-n6gwz.etlservicemgr > gateway.50622: P 176:211(35) ack 286 win 69 IP gateway.50622 > mmlservice-84c994bbfd-n6gwz.etlservicemgr: . ack 211 win 92