search

warmcat / libwebsockets

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

is timeout_secs and ws_ping_pong_interval not working? #1283

Closed kclyu closed 6 years ago

kclyu commented 6 years ago

f websocket is idle and there is no transmission, try to check if the session is alive using ping / pong. I remember that it worked in the old 2.2 version, but now master / 3.0 does not seem to work.

Below are the log messages tested with 2.2 and 3.0/master's libwebsocket-test-server and client. In 2.2 below, connection is not released by timeout after ping/pong message exchange. In 3.0/master, normal idle session is closed when there is no ping/pong message exchange and timeout occurs.

Even if the server program sends a ping/pong message by modifying the server program, the idle session is closed as well.

Building comand line options and environment

Building command line

cmake ..  -DCMAKE_BUILD_TYPE=Debug -DLWS_WITH_SSL=OFF -DLWS_WITH_SHARED=OFF -DLWS_WITH_LIBEV=0 && make

Building OS Raspberry PI native/Ubuntu 16.04 Cross Compile (The same result in both environments)

2.2 libwebsockets

server log

./libwebsockets-test-server -v -d 991 -P 1
[2018/05/22 03:14:03:2067] NOTICE: Setting pingpong interval to 1
lwsts[25377]: libwebsockets test server - license LGPL2.1+SLE
lwsts[25377]: (C) Copyright 2010-2016 Andy Green <andy@warmcat.com>
Using resource path "/usr/local/share/libwebsockets-test-server"
lwsts[25377]: Initial logging level 991
lwsts[25377]: Libwebsockets version: 2.2.0 kclyu@keunchang2-v0.65-48-g2cc725a
lwsts[25377]: IPV6 not compiled in
lwsts[25377]: libev support not compiled in
lwsts[25377]: libuv support not compiled in
lwsts[25377]:  LWS_DEF_HEADER_LEN    : 4096
lwsts[25377]:  LWS_MAX_PROTOCOLS     : 5
lwsts[25377]:  LWS_MAX_SMP           : 32
lwsts[25377]:  SPEC_LATEST_SUPPORTED : 13
lwsts[25377]:  sizeof (*info)        : 344
lwsts[25377]:  SYSTEM_RANDOM_FILEPATH: '/dev/urandom'
lwsts[25377]:  default timeout (secs): 5
lwsts[25377]:  Threads: 1 each 1024 fds
lwsts[25377]:  mem: context:          9008 bytes (4912 ctx + (1 thr x 4096))
lwsts[25377]:  mem: http hdr rsvd:   123392 bytes (1 thr x (4096 + 3616) x 16))
lwsts[25377]:  mem: pollfd map:       8192
lwsts[25377]:  mem: platform fd map:  8192 bytes
lwsts[25377]: Creating Vhost 'default' port 7681, 5 protocols, IPv6 off
lwsts[25377]: insert_wsi_socket_into_fds: 0x7e76c0: tsi=0, sock=7, pos-in-fds=1
lwsts[25377]:  Listening on port 7681
lwsts[25377]:  LWS_MAX_EXTENSIONS_ACTIVE: 2
lwsts[25377]:  mem: per-conn:          536 bytes + protocol rx buf
lwsts[25377]:  canonical_hostname = keunchang2
lwsts[25377]: lws_protocol_init
lwsts[25377]: accepted new conn  port 35531 on fd=8
lwsts[25377]: Accepted wsi 0x7e78e0 to context 0x7e83c0, tsi 0
lwsts[25377]: lws_adopt_descriptor_vhost: new wsi 0x7e78e0, sockfd 8
lwsts[25377]: lws_set_timeout: 0x7e78e0: 5 secs
...
lwsts[25377]: lws_calllback_as_writeable: 0x7e78e0 (user=0x7e7d20)
lwsts[25377]: _lws_rx_flow_control: no pending change
lwsts[25377]: lws_calllback_as_writeable: 0x7e78e0 (user=0x7e7d20)
lwsts[25377]: _lws_rx_flow_control: no pending change
lwsts[25377]: requesting ping-pong on wsi 0x7e7b00
lwsts[25377]: lws_set_timeout: 0x7e7b00: 5 secs
lwsts[25377]: issuing ping on wsi 0x7e7b00
lwsts[25377]: lws_set_timeout: 0x7e7b00: 5 secs
lwsts[25377]: lws_calllback_as_writeable: 0x7e78e0 (user=0x7e7d20)
lwsts[25377]: _lws_rx_flow_control: no pending change
lwsts[25377]: lws_calllback_as_writeable: 0x7e7b00 (user=0x7e7e10)
lwsts[25377]: _lws_rx_flow_control: no pending change
lwsts[25377]: lws_read: incoming len 6  state 5
lwsts[25377]: received pong
lwsts[25377]: 
lwsts[25377]: received expected PONG on wsi 0x7e7b00
lwsts[25377]: lws_set_timeout: 0x7e7b00: 0 secs
lwsts[25377]: lws_rx_sm: passing 0 to ext
lwsts[25377]:  lws_extension_callback_pm_deflate: LWS_EXT_CB_PAYLOAD_RX: in 0, existing in 0
lwsts[25377]: Doing pong callback

...

client log

kclyu@keunchang2:~/Workspace/rpi-webrtc-streamer/lib/libwebsockets-2.2/build/bin$ ./libwebsockets-test-client localhost -p 7681 -n   -e
[2018/05/22 03:15:11:9214] NOTICE: libwebsockets test client - license LGPL2.1+SLE
[2018/05/22 03:15:11:9215] NOTICE: (C) Copyright 2010-2016 Andy Green <andy@warmcat.com>
[2018/05/22 03:15:11:9215] NOTICE: Disabled sending mirror data (for pingpong testing)
./libwebsockets-test-client: invalid option -- 'e'
[2018/05/22 03:15:11:9216] NOTICE:  SSL disabled
[2018/05/22 03:15:11:9217] NOTICE:  Cert must validate correctly (use -s to allow selfsigned)
[2018/05/22 03:15:11:9217] NOTICE:  Requiring peer cert hostname matches
[2018/05/22 03:15:11:9217] NOTICE: Initial logging level 7
[2018/05/22 03:15:11:9217] NOTICE: Libwebsockets version: 2.2.0 kclyu@keunchang2-v0.65-48-g2cc725a
[2018/05/22 03:15:11:9217] NOTICE: IPV6 not compiled in
[2018/05/22 03:15:11:9218] NOTICE: libev support not compiled in
[2018/05/22 03:15:11:9218] NOTICE: libuv support not compiled in
[2018/05/22 03:15:11:9219] NOTICE:  Threads: 1 each 1024 fds
[2018/05/22 03:15:11:9219] NOTICE:  mem: platform fd map:  8192 bytes
[2018/05/22 03:15:11:9219] NOTICE: Creating Vhost 'default' port -1, 3 protocols, IPv6 off
[2018/05/22 03:15:11:9219] NOTICE:  mem: per-conn:          536 bytes + protocol rx buf
[2018/05/22 03:15:11:9219] NOTICE:  canonical_hostname = keunchang2
[2018/05/22 03:15:11:9219] NOTICE: using  mode (ws)
[2018/05/22 03:15:11:9219] NOTICE: dumb: connecting
[2018/05/22 03:15:11:9220] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:11:9223] NOTICE: mirror: connecting
[2018/05/22 03:15:11:9223] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:11:9224] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:11:9225] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:11:9235] NOTICE: checking client ext permessage-deflate
[2018/05/22 03:15:11:9235] NOTICE: instantiating client ext permessage-deflate
[2018/05/22 03:15:11:9235] ERR:  Capping pmd rx to 128
[2018/05/22 03:15:11:9235] NOTICE: mirror: LWS_CALLBACK_CLIENT_ESTABLISHED
[2018/05/22 03:15:38:1521] NOTICE: mirror: LWS_CALLBACK_CLOSED mirror_lifetime=78863
[2018/05/22 03:15:38:1522] NOTICE: mirror: connecting
[2018/05/22 03:15:38:1523] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:38:1531] NOTICE: dumb: LWS_CALLBACK_CLOSED
[2018/05/22 03:15:38:1533] NOTICE: dumb: connecting
[2018/05/22 03:15:38:1533] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:38:1543] ERR: CLIENT_CONNECTION_ERROR: mirror: (null)
[2018/05/22 03:15:38:1544] ERR: CLIENT_CONNECTION_ERROR: dumb: (null)
[2018/05/22 03:15:40:1568] NOTICE: dumb: connecting
[2018/05/22 03:15:40:1569] NOTICE: lws_client_connect_2: address localhost
[2018/05/22 03:15:40:1572] NOTICE: mirror: connecting
[2018/05/22 03:15:40:1572] NOTICE: lws_client_connect_2: address localhost

master/3.0-stable

server log

./libwebsockets-test-server -v -d 991 -P 1
[2018/05/22 12:16:59:7745] NOTICE: Setting pingpong interval to 1
[2018/05/22 12:16:59:7746] NOTICE: libwebsockets test server - license LGPL2.1+SLE
[2018/05/22 12:16:59:7746] NOTICE: (C) Copyright 2010-2018 Andy Green <andy@warmcat.com>
Using resource path "/usr/local/share/libwebsockets-test-server"
[2018/05/22 12:16:59:7747] INFO: Initial logging level 991
[2018/05/22 12:16:59:7747] INFO: Libwebsockets version: 3.0.99 v3.0.0-15-g621cdd7c
[2018/05/22 12:16:59:7748] INFO: IPV6 not compiled in
[2018/05/22 12:16:59:7748] INFO:  LWS_DEF_HEADER_LEN    : 4096
[2018/05/22 12:16:59:7748] INFO:  LWS_MAX_PROTOCOLS     : 5
[2018/05/22 12:16:59:7749] INFO:  LWS_MAX_SMP           : 1
[2018/05/22 12:16:59:7749] INFO:  sizeof (*info)        : 276
[2018/05/22 12:16:59:7749] INFO:  SYSTEM_RANDOM_FILEPATH: '/dev/urandom'
[2018/05/22 12:16:59:7750] INFO:  HTTP2 support         : not configured
[2018/05/22 12:16:59:7750] DEBUG: _realloc: size 488: context
[2018/05/22 12:16:59:7751] INFO: Using event loop: poll
[2018/05/22 12:16:59:7751] INFO:  default timeout (secs): 5
[2018/05/22 12:16:59:7751] DEBUG: _realloc: size 4096: pt_serv_buf
[2018/05/22 12:16:59:7752] INFO:  Threads: 1 each 1024 fds
[2018/05/22 12:16:59:7752] INFO:  mem: context:          4584 B (488 ctx + (1 thr x 4096))
[2018/05/22 12:16:59:7752] INFO:  mem: http hdr rsvd:   5152768 B (1 thr x (4096 + 936) x 1024))
[2018/05/22 12:16:59:7753] DEBUG: _realloc: size 8192: fds table
[2018/05/22 12:16:59:7753] INFO:  mem: pollfd map:       8192
[2018/05/22 12:16:59:7754] DEBUG: _realloc: size 4096: lws_lookup
[2018/05/22 12:16:59:7754] INFO:  mem: platform fd map:  4096 bytes
[2018/05/22 12:16:59:7755] DEBUG: _realloc: size 272: event pipe wsi
[2018/05/22 12:16:59:7755] DEBUG: lws_role_transition: 0x637648: wsistate 0x200, ops pipe
[2018/05/22 12:16:59:7756] DEBUG: event pipe fd 4
[2018/05/22 12:16:59:7756] DEBUG: __insert_wsi_socket_into_fds: 0x637648: tsi=0, sock=4, pos-in-fds=0
[2018/05/22 12:16:59:7757] INFO:  mem: per-conn:          272 bytes + protocol rx buf
[2018/05/22 12:16:59:7758] INFO:  canonical_hostname = raspberrypi3
[2018/05/22 12:16:59:7758] INFO: lws_cancel_service
[2018/05/22 12:16:59:7759] DEBUG: _realloc: size 424: create vhost
[2018/05/22 12:16:59:7759] DEBUG: _realloc: size 168: vhost-specific plugin table
[2018/05/22 12:16:59:7759] DEBUG: _realloc: size 20: same vh list
[2018/05/22 12:16:59:7760] NOTICE: Creating Vhost 'default' port 7681, 5 protocols, IPv6 off
[2018/05/22 12:16:59:7761] INFO:    mounting file:///usr/local/share/libwebsockets-test-server to /
[2018/05/22 12:16:59:7761] INFO:    mounting callback://protocol-post-demo to /formtest
[2018/05/22 12:16:59:7761] INFO:    mounting file:///usr/local/share/libwebsockets-test-server/candide.zip to /ziptest
[2018/05/22 12:16:59:7763] DEBUG: _lws_vhost_init_server: lws_socket_bind says 7681
[2018/05/22 12:16:59:7763] DEBUG: _realloc: size 272: listen wsi
[2018/05/22 12:16:59:7763] DEBUG: lws_role_transition: 0x6379d8: wsistate 0x200, ops listen
[2018/05/22 12:16:59:7764] DEBUG: __insert_wsi_socket_into_fds: 0x6379d8: tsi=0, sock=6, pos-in-fds=1
[2018/05/22 12:16:59:7765] INFO: lws_protocol_init
[2018/05/22 12:16:59:7765] DEBUG:     vhost "default", protocol "dumb-increment-protocol", option "options"
[2018/05/22 12:16:59:7766] DEBUG: _realloc: size 20: protocol_vh_privs
[2018/05/22 12:16:59:7766] DEBUG: _realloc: size 4: vh priv
[2018/05/22 12:16:59:7766] DEBUG: _realloc: size 4: vh priv
[2018/05/22 12:16:59:7767] DEBUG: _realloc: size 20: vh priv
[2018/05/22 12:16:59:7768] INFO: LWS_CALLBACK_EVENT_WAIT_CANCELLED
[2018/05/22 12:17:01:8003] DEBUG: accepted new conn port 51318 on fd=7
[2018/05/22 12:17:01:8004] DEBUG: _realloc: size 272: new server wsi
[2018/05/22 12:17:01:8004] DEBUG: new wsi 0x637b40 joining vhost default, tsi 0
[2018/05/22 12:17:01:8005] DEBUG: lwsi_set_state(0x637b40, 0x200)
[2018/05/22 12:17:01:8005] DEBUG: lws_role_transition: 0x637b40: wsistate 0x20000015, ops h1
[2018/05/22 12:17:01:8006] DEBUG: __lws_set_timeout: 0x637b40: 5 secs
[2018/05/22 12:17:01:8006] DEBUG: new wsi wsistate 0x20000015
[2018/05/22 12:17:01:8006] DEBUG: __insert_wsi_socket_into_fds: 0x637b40: tsi=0, sock=7, pos-in-fds=2
[2018/05/22 12:17:01:8007] INFO: lws_header_table_attach: wsi 0x637b40: ah (nil) (tsi 0, count = 0) in
[2018/05/22 12:17:01:8007] DEBUG: _realloc: size 936: ah struct
[2018/05/22 12:17:01:8008] DEBUG: _realloc: size 4096: ah data
[2018/05/22 12:17:01:8008] INFO: _lws_create_ah: created ah 0x637c58 (size 4096): pool length 1
[2018/05/22 12:17:01:8009] DEBUG: _lws_change_pollfd: wsi 0x637b40: fd 7 events 1 -> 1
[2018/05/22 12:17:01:8009] INFO: lws_header_table_attach: did attach wsi 0x637b40: ah 0x637c58: count 1 (on exit)
[2018/05/22 12:17:01:8009] DEBUG: __lws_set_timeout: 0x637b40: 10 secs
[2018/05/22 12:17:01:8010] DEBUG: Attached ah immediately
[2018/05/22 12:17:01:8010] INFO: rops_handle_POLLIN_listen: new wsi 0x637b40: wsistate 0x20000015, role_ops h1
[2018/05/22 12:17:01:8011] INFO: LWS_CALLBACK_EVENT_WAIT_CANCELLED
[2018/05/22 12:17:01:8011] DEBUG: rops_handle_POLLIN_h1: 0x637b40: wsistate 0x20000015
[2018/05/22 12:17:01:8013] INFO: lws_handshake_server: parsed count 263
[2018/05/22 12:17:01:8013] INFO: lws_select_vhost: vhost match to default based on port 7681
[2018/05/22 12:17:01:8014] DEBUG: lwsi_set_state(0x637b40, 0x20000209)
[2018/05/22 12:17:01:8014] DEBUG: __lws_set_timeout: 0x637b40: 0 secs
[2018/05/22 12:17:01:8014] INFO: Upgrade to ws
[2018/05/22 12:17:01:8015] DEBUG: checking lws-mirror-protocol
[2018/05/22 12:17:01:8015] DEBUG: try http-only
[2018/05/22 12:17:01:8015] DEBUG: try dumb-increment-protocol
[2018/05/22 12:17:01:8017] DEBUG: try lws-mirror-protocol
[2018/05/22 12:17:01:8018] DEBUG: _realloc: size 180: ws struct
[2018/05/22 12:17:01:8018] DEBUG: _realloc: size 16: user space
[2018/05/22 12:17:01:8019] DEBUG: lws_ensure_user_space: 0x637b40 protocol pss 16, user_space=0x6380c0
[2018/05/22 12:17:01:8020] DEBUG: lwsi_set_state(0x637b40, 0x20000117)
[2018/05/22 12:17:01:8021] DEBUG: lws_role_transition: 0x637b40: wsistate 0x20000117, ops ws
[2018/05/22 12:17:01:8021] DEBUG: lwsi_set_state(0x637b40, 0x20000117)
[2018/05/22 12:17:01:8021] DEBUG: _realloc: size 4116: rx_ubuf
[2018/05/22 12:17:01:8022] DEBUG: Allocating RX buffer 4112
[2018/05/22 12:17:01:8022] INFO: callback_lws_mirror: LWS_CALLBACK_ESTABLISHED
[2018/05/22 12:17:01:8023] NOTICE: callback_lws_mirror: mirror name ''
[2018/05/22 12:17:01:8023] DEBUG: _realloc: size 24: ring create
[2018/05/22 12:17:01:8023] DEBUG: _realloc: size 256: ring buf
[2018/05/22 12:17:01:8024] NOTICE: Created new mi 0x6380d8 ''
[2018/05/22 12:17:01:8024] DEBUG: ws established
[2018/05/22 12:17:01:8025] INFO: lws_process_ws_upgrade: 0x637b40: dropping ah on ws upgrade
[2018/05/22 12:17:01:8025] INFO: __lws_header_table_detach: wsi 0x637b40: ah 0x637c58 (tsi=0, count = 1)
[2018/05/22 12:17:01:8025] INFO: __lws_header_table_detach: nobody usable waiting
[2018/05/22 12:17:01:8026] INFO: _lws_destroy_ah: freed ah 0x637c58 : pool length 0
[2018/05/22 12:17:01:8026] INFO: __lws_header_table_detach: wsi 0x637b40: ah 0x637c58 (tsi=0, count = 0)
[2018/05/22 12:17:01:8027] DEBUG: lws_h1_server_socket_service: consumed 263
[2018/05/22 12:17:03:0048] INFO: req pp on wsi 0x637b40
[2018/05/22 12:17:03:0048] DEBUG: __lws_set_timeout: 0x637b40: 5 secs
[2018/05/22 12:17:03:0049] DEBUG: _lws_change_pollfd: wsi 0x637b40: fd 7 events 1 -> 5
[2018/05/22 12:17:03:0049] DEBUG: _lws_change_pollfd: wsi 0x637b40: fd 7 events 5 -> 1
[2018/05/22 12:17:03:0050] DEBUG: lws_handle_POLLOUT_event: 0x637b40: non mux: wsistate 0x20000117, ops ws
[2018/05/22 12:17:09:0156] INFO: wsi 0x637b40: TIMEDOUT WAITING on 16 (did hdr 1, ah (nil), wl 0, pfd events 1) 1526959029 vs 5
[2018/05/22 12:17:09:0157] INFO: __lws_close_free_wsi: 0x637b40: caller: timeout
[2018/05/22 12:17:09:0157] DEBUG: __lws_close_free_wsi: real just_kill_connection: 0x637b40 (sockfd 7)
[2018/05/22 12:17:09:0158] INFO: lws_same_vh_protocol_remove: removing same prot wsi 0x637b40
[2018/05/22 12:17:09:0158] INFO: have prev 0x6379c8, setting him to our next (nil)
[2018/05/22 12:17:09:0159] DEBUG: __remove_wsi_socket_from_fds: wsi=0x637b40, sock=7, fds pos=2, end guy pos=3, endfd=0
[2018/05/22 12:17:09:0159] DEBUG: _lws_change_pollfd: wsi 0x6379d8: fd 6 events 1 -> 1
[2018/05/22 12:17:09:0161] DEBUG: lwsi_set_state(0x637b40, 0x2000001e)
[2018/05/22 12:17:09:0192] DEBUG: __lws_free_wsi: 0x637b40, remaining wsi 2

client log

pi@raspberrypi3:~/Workspace/libwebsockets/build/bin $ ./libwebsockets-test-client 10.0.0.12 -p 7681 -n   -e
[2018/05/22 12:17:01:7988] NOTICE: libwebsockets test client - license LGPL2.1+SLE
[2018/05/22 12:17:01:7989] NOTICE: (C) Copyright 2010-2018 Andy Green <andy@warmcat.com>
[2018/05/22 12:17:01:7990] NOTICE: Disabled sending mirror data (for pingpong testing)
[2018/05/22 12:17:01:7991] NOTICE:  SSL disabled
[2018/05/22 12:17:01:7991] NOTICE:  Cert must validate correctly (use -s to allow selfsigned)
[2018/05/22 12:17:01:7992] NOTICE:  Requiring peer cert hostname matches
[2018/05/22 12:17:01:7995] NOTICE: Creating Vhost 'default' (serving disabled), 3 protocols, IPv6 off
[2018/05/22 12:17:01:7996] NOTICE: using  mode (ws)
[2018/05/22 12:17:01:7997] NOTICE: mirror: connecting
[2018/05/22 12:17:01:8029] NOTICE: mirror: LWS_CALLBACK_CLIENT_ESTABLISHED
[2018/05/22 12:17:02:3036] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:03:3048] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:04:3060] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:05:3072] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:06:3084] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:07:3096] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:08:3108] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:09:0164] NOTICE: mirror: LWS_CALLBACK_CLOSED mirror_lifetime=0, rxb 0, rx_count 0
[2018/05/22 12:17:09:0166] NOTICE: rxb 0, rx_count 0
[2018/05/22 12:17:09:0167] ERR: Exiting
lws-team commented 6 years ago

Hm this works fine (client sending pings)

 $ libwebsockets-test-server
 $ libwebsockets-test-client  localhost -p 7681 -n   -e -P3

Client is sending PING at 3s intervals and server is responding with PONG immediately.

I poked around a bit and saw the pingpong stuff had accidentally become client-only during the role refactoring before v3.0. I pushed a patch on both master and v3.0-stable that should return it to normal.

kclyu commented 6 years ago

Thank you for quick response. ping/pong works well on server. I will close this issue.