search

slact / nchan

Fast, horizontally scalable, multiprocess pub/sub queuing server and proxy for HTTP, long-polling, Websockets and EventSource (SSE), powered by Nginx.
https://nchan.io/
Other
3.01k stars 292 forks source link

nchan 1.2.1 with redis crashes immediately (nchan -> haproxy -> redis master) #481

Closed outcassed closed 1 year ago

outcassed commented 6 years ago

I tried upgrading from nchan 1.1.16 and nginx crashes right after startup every time

nginx error log:

2018/08/13 08:29:18 [info] 16219#0: Using 524288KiB of shared memory for nchan in /etc/nginx/nginx.conf:119
2018/08/13 08:29:22 [alert] 16422#0: worker process 16423 exited on signal 11 (core dumped)
ker process: /usr/local/src/nchan-1.2.1/src/store/redis/redis_nodeset.c:821: node_set_role: Assertion `(*cur)->peers.master == node' failed.

trace:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x0000564a3aed6d9d in node_connector_callback (ac=ac@entry=0x0, rep=rep@entry=0x0, privdata=privdata@entry=0x564a3d5cf7e0)
    at /usr/local/src/nchan-1.2.1/src/store/redis/redis_nodeset.c:1345
1345          if(!node->ping_timer.timer_set && nodeset->settings.ping_interval > 0) {
(gdb) bt
#0  0x0000564a3aed6d9d in node_connector_callback (ac=ac@entry=0x0, rep=rep@entry=0x0, privdata=privdata@entry=0x564a3d5cf7e0)
    at /usr/local/src/nchan-1.2.1/src/store/redis/redis_nodeset.c:1345
#1  0x0000564a3aed67dd in node_connector_callback (ac=<optimized out>, rep=0x564a3d651c90, privdata=0x564a3d5cf7e0)
    at /usr/local/src/nchan-1.2.1/src/store/redis/redis_nodeset.c:1260
#2  0x0000564a3aecabe9 in __redisRunCallback (ac=ac@entry=0x564a3d523030, cb=cb@entry=0x7ffded39b3d0, reply=<optimized out>)
    at /usr/local/src/nchan-1.2.1/src/hiredis/async.c:269
#3  0x0000564a3aecbd6c in redisProcessCallbacks (ac=ac@entry=0x564a3d523030) at /usr/local/src/nchan-1.2.1/src/hiredis/async.c:469
#4  0x0000564a3aecbe0e in redisAsyncHandleRead (ac=ac@entry=0x564a3d523030) at /usr/local/src/nchan-1.2.1/src/hiredis/async.c:533
#5  0x0000564a3aede054 in redis_nginx_read_event (ev=0x7f6d0ac161b0) at /usr/local/src/nchan-1.2.1/src/store/redis/redis_nginx_adapter.c:143
#6  0x0000564a3ae2489d in ngx_epoll_process_events (cycle=0x564a3d4266f0, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:902
#7  0x0000564a3ae19750 in ngx_process_events_and_timers (cycle=cycle@entry=0x564a3d4266f0) at src/event/ngx_event.c:242
#8  0x0000564a3ae223fc in ngx_worker_process_cycle (cycle=cycle@entry=0x564a3d4266f0, data=data@entry=0x0) at src/os/unix/ngx_process_cycle.c:750
#9  0x0000564a3ae2066d in ngx_spawn_process (cycle=cycle@entry=0x564a3d4266f0, proc=0x564a3ae222f7 <ngx_worker_process_cycle>, data=0x0,
    name=0x564a3b08b0ab "worker process", respawn=respawn@entry=0) at src/os/unix/ngx_process.c:199
#10 0x0000564a3ae230bb in ngx_reap_children (cycle=0x564a3d4266f0) at src/os/unix/ngx_process_cycle.c:622
#11 ngx_master_process_cycle (cycle=0x564a3d4266f0) at src/os/unix/ngx_process_cycle.c:175
#12 0x0000564a3adf8ab2 in main (argc=3, argv=<optimized out>) at src/core/nginx.c:382

nginx version:

nginx version: nginx/1.14.0
built by gcc 7.3.0 (Gentoo 7.3.0-r3 p1.4)
built with OpenSSL 1.1.0h  27 Mar 2018
TLS SNI support enabled
configure arguments: --prefix=/opt/nginx.build --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access_log --error-log-path=/var/log/nginx/error_log --pid-path=/var/run/nginx.pid --http-client-body-temp-path=/var/tmp/nginx/client --http-proxy-temp-path=/var/tmp/nginx/proxy/ --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi --with-http_stub_status_module --with-http_v2_module --with-http_ssl_module --with-openssl=/usr/local/src/openssl-1.1.0h --add-module=/usr/local/src/nchan-1.2.1 --with-debug --with-cc-opt='-g'
slact commented 6 years ago

What's your Nginx config? What Redis server version are you connecting to, and what is the topology? (Master-slave, cluster, etc)?

outcassed commented 6 years ago

A single Redis server, version 4.0.1

nginx config uses nchan_redis_url but when I upgraded I got warnings so I also tried it with nchan_redis_pass and upstream.

I've been using 1 worker so that I can auto restart nginx when the worker crashes. It's better if the whole thing becomes unresponsive when a worker dies.

user nginx nginx;
worker_processes  1;
worker_rlimit_nofile 131072;
worker_shutdown_timeout 60s;

worker_rlimit_core  1000M;
working_directory /home/nginx;

error_log /var/log/nginx/error_log warn;

events {
    accept_mutex on;
    worker_connections  64000;
    use epoll;
}

http {
  include       /etc/nginx/mime.types;
  default_type  application/octet-stream;
  access_log off;

  nchan_max_reserved_memory 512M;
  nchan_subscriber_timeout 60m;
  nchan_max_channel_id_length 2048;
  nchan_message_timeout 10m;

  nchan_use_redis on;
  nchan_redis_url "redis://192.168.1.30:6379";
  nchan_redis_namespace nchan;

  server {
    listen 80;
    listen 443 ssl http2;

    root /var/www/sites/default;

    location ~ /nchan/pub {
      nchan_publisher;
      nchan_use_redis on;
      nchan_channel_id $arg_id;
      nchan_message_buffer_length 200;
      break;
    }

    location ~ /nchan/sub {
      nchan_subscriber;
      nchan_use_redis on;
      nchan_subscriber_first_message newest;

      nchan_message_buffer_length 200;

      nchan_channel_id $arg_id;
      nchan_channel_id_split_delimiter ",";
      nchan_subscriber_first_message newest;
      break;
    }

    location /nchan/status {
      nchan_stub_status;
    }
 }

}
slact commented 6 years ago

can you set error_log level to info and show me the log from starting nginx to the crash?

After that, set it to debug, and paste from start to crash as well?

outcassed commented 6 years ago

info:

2018/08/14 15:12:43 [warn] 26406#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:46
2018/08/14 15:12:43 [warn] 26406#0: Use of nchan_redis_url is discouraged in favor of an upstream { } block with nchan_redis_server redis://192.168.220.30:6379; in /etc/nginx/ng
inx.conf:47
2018/08/14 15:12:43 [warn] 26406#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:73
2018/08/14 15:12:43 [warn] 26406#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:88
2018/08/14 15:12:43 [info] 26406#0: Using 524288KiB of shared memory for nchan in /etc/nginx/nginx.conf:119
2018/08/14 15:12:43 [warn] 26410#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:46
2018/08/14 15:12:43 [warn] 26410#0: Use of nchan_redis_url is discouraged in favor of an upstream { } block with nchan_redis_server redis://192.168.220.30:6379; in /etc/nginx/ng
inx.conf:47
2018/08/14 15:12:43 [warn] 26410#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:73
2018/08/14 15:12:43 [warn] 26410#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:88
2018/08/14 15:12:43 [notice] 26410#0: using the "epoll" event method
2018/08/14 15:12:43 [notice] 26410#0: nginx/1.14.0
2018/08/14 15:12:43 [notice] 26410#0: built by gcc 7.3.0 (Gentoo 7.3.0-r3 p1.4)
2018/08/14 15:12:43 [notice] 26410#0: OS: Linux 4.8.0-gentoo
2018/08/14 15:12:43 [notice] 26410#0: getrlimit(RLIMIT_NOFILE): 1024:4096
2018/08/14 15:12:43 [notice] 26411#0: start worker processes
2018/08/14 15:12:43 [notice] 26411#0: start worker process 26412
2018/08/14 15:12:44 [info] 26412#0: *1 client closed connection while waiting for request, client: 132.183.13.2, server: 0.0.0.0:443
2018/08/14 15:12:44 [info] 26412#0: *15 client closed connection while waiting for request, client: 38.140.162.210, server: 0.0.0.0:443
2018/08/14 15:12:44 [notice] 26412#0: nchan: Redis node 192.168.220.30:6379 Discovering own slave 192.168.220.30:6379
2018/08/14 15:12:44 [notice] 26412#0: nchan: Redis node 192.168.220.30:6379 connected
2018/08/14 15:12:44 [info] 26412#0: *31 client closed connection while waiting for request, client: 132.183.13.2, server: 0.0.0.0:443
2018/08/14 15:12:44 [info] 26412#0: *6 client closed connection while waiting for request, client: 143.231.249.141, server: 0.0.0.0:443
2018/08/14 15:12:44 [info] 26412#0: *24 client 207.237.170.10 closed keepalive connection
2018/08/14 15:12:44 [info] 26412#0: *30 client closed connection while waiting for request, client: 132.183.56.7, server: 0.0.0.0:443
2018/08/14 15:12:44 [info] 26412#0: *13 client 71.185.194.6 closed keepalive connection
2018/08/14 15:12:44 [info] 26412#0: *49 client 128.197.121.220 closed keepalive connection
2018/08/14 15:12:44 [info] 26412#0: *10 client 73.182.252.194 closed keepalive connection
2018/08/14 15:12:44 [info] 26412#0: *11 client 76.117.93.228 closed keepalive connection
2018/08/14 15:12:44 [info] 26412#0: *23 client 100.40.81.110 closed keepalive connection
2018/08/14 15:12:44 [notice] 26412#0: nchan: Redis node 192.168.220.140:6379 Discovering own master 192.168.220.140:6379
2018/08/14 15:12:46 [notice] 26411#0: signal 17 (SIGCHLD) received from 26412
2018/08/14 15:12:46 [alert] 26411#0: worker process 26412 exited on signal 11 (core dumped)
``

debug:

2018/08/14 15:13:40 [warn] 37934#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:46 2018/08/14 15:13:40 [warn] 37934#0: Use of nchan_redis_url is discouraged in favor of an upstream { } block with nchan_redis_server redis://192.168.220.30:6379; in /etc/nginx/nginx.conf:47 2018/08/14 15:13:40 [warn] 37934#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:73 2018/08/14 15:13:40 [warn] 37934#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:88 2018/08/14 15:13:40 [info] 37934#0: Using 524288KiB of shared memory for nchan in /etc/nginx/nginx.conf:119 2018/08/14 15:13:40 [debug] 37934#0: bind() 0.0.0.0:80 #5 2018/08/14 15:13:40 [debug] 37934#0: bind() 0.0.0.0:443 #5 2018/08/14 15:13:40 [debug] 37934#0: counter: 00007F84D6FB4080, 1 2018/08/14 15:13:41 [warn] 38164#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:46 2018/08/14 15:13:41 [warn] 38164#0: Use of nchan_redis_url is discouraged in favor of an upstream { } block with nchan_redis_server redis://192.168.220.30:6379; in /etc/nginx/nginx.conf:47 2018/08/14 15:13:41 [warn] 38164#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:73 2018/08/14 15:13:41 [warn] 38164#0: Use of nchan_use_redis is discouraged in favor of nchan_redis_pass. in /etc/nginx/nginx.conf:88 2018/08/14 15:13:41 [debug] 38164#0: bind() 0.0.0.0:80 #5 2018/08/14 15:13:41 [debug] 38164#0: bind() 0.0.0.0:443 #6 2018/08/14 15:13:41 [notice] 38164#0: using the "epoll" event method 2018/08/14 15:13:41 [debug] 38164#0: counter: 00007F2241D37080, 1 2018/08/14 15:13:41 [notice] 38164#0: nginx/1.14.0 2018/08/14 15:13:41 [notice] 38164#0: built by gcc 7.3.0 (Gentoo 7.3.0-r3 p1.4) 2018/08/14 15:13:41 [notice] 38164#0: OS: Linux 4.8.0-gentoo 2018/08/14 15:13:41 [notice] 38164#0: getrlimit(RLIMIT_NOFILE): 1024:4096 2018/08/14 15:13:41 [debug] 38165#0: write: 9, 00007FFD8C66E2F0, 6, 0 2018/08/14 15:13:41 [debug] 38165#0: setproctitle: "nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf" 2018/08/14 15:13:41 [notice] 38165#0: start worker processes 2018/08/14 15:13:41 [debug] 38165#0: channel 3:9 2018/08/14 15:13:41 [notice] 38165#0: start worker process 38166 2018/08/14 15:13:41 [debug] 38165#0: sigsuspend 2018/08/14 15:13:41 [debug] 38166#0: add cleanup: 000055D17B792F00 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B79EC60:8 2018/08/14 15:13:41 [debug] 38166#0: notify eventfd: 11 2018/08/14 15:13:41 [debug] 38166#0: testing the EPOLLRDHUP flag: success 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B76F1E0:6144 2018/08/14 15:13:41 [debug] 38166#0: malloc: 00007F221C421010:14848000 2018/08/14 15:13:41 [debug] 38166#0: malloc: 00007F221BE44010:6144000 2018/08/14 15:13:41 [debug] 38166#0: malloc: 00007F221B867010:6144000 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:5 op:1 ev:00002001 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:6 op:1 ev:00002001 2018/08/14 15:13:41 [debug] 38166#0: REAPER: start reaper memstore message with tick time of 5 sec 2018/08/14 15:13:41 [debug] 38166#0: REAPER: start reaper memstore nobuffer message with tick time of 2 sec 2018/08/14 15:13:41 [debug] 38166#0: REAPER: start reaper chanhead with tick time of 4 sec 2018/08/14 15:13:41 [debug] 38166#0: REAPER: start reaper chanhead churner with tick time of 10 sec 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:7 op:1 ev:00002001 2018/08/14 15:13:41 [debug] 38166#0: MEMSTORE:00: init memstore worker pid:38166 slot:0 max workers :1 or 1 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: MEMSTORE:00: found my procslot (ngx_process_slot 0, procslot 0) 2018/08/14 15:13:41 [debug] 38166#0: MEMSTORE:00: shm: 000055D17B79EE80, shdata: 00007F221D547000 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: REDIS NODESET: connect all 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B753CD0:664 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 created 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 start connecting 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 0 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:1 ev:80000004 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B753FF0:104 2018/08/14 15:13:41 [debug] 38166#0: event timer add: 14: 600:56701156028 2018/08/14 15:13:41 [debug] 38166#0: WEBSOCKET_PUBLISHER:init WS publisher llist 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B796FA0:152 2018/08/14 15:13:41 [debug] 38166#0: THINGCACHE: init fd_cache 000055D17B796FA0 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:9 op:1 ev:00002001 2018/08/14 15:13:41 [debug] 38166#0: setproctitle: "nginx: worker process" 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 1 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:3 op:1 ev:80000004 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:2 ev:00000000 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 19 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B754660:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 1 accept: 75.68.38.229:56875 fd:13 2018/08/14 15:13:41 [debug] 38166#0: 1 event timer add: 13: 60000:56701215447 2018/08/14 15:13:41 [debug] 38166#0: 1 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 1 epoll add event: fd:13 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:3 ev:0004 d:00007F221C421498 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 2 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 6 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 9 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:3 op:2 ev:00000000 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:3 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 581 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 580 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 580 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 580 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 580 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 579 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 579 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 579 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 579 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 578 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 578 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 577 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 577 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B754B40:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 2 accept: 98.113.60.241:57431 fd:14 2018/08/14 15:13:41 [debug] 38166#0: 2 event timer add: 14: 60000:56701215452 2018/08/14 15:13:41 [debug] 38166#0: 2 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 2 epoll add event: fd:14 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 576 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 576 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 576 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:14 ev:0001 d:00007F221C421668 2018/08/14 15:13:41 [debug] 38166#0: 2 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 2 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 2 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 2 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 2 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 576 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:13 ev:0001 d:00007F221C421580 2018/08/14 15:13:41 [debug] 38166#0: 1 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 1 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 1 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 1 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 1 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 1 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 1 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 1 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 3 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 573 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B768470:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 3 accept: 204.13.41.250:43754 fd:15 2018/08/14 15:13:41 [debug] 38166#0: 3 event timer add: 15: 60000:56701215456 2018/08/14 15:13:41 [debug] 38166#0: 3 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 3 epoll add event: fd:15 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 572 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B766D10:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 4 accept: 204.40.130.133:61518 fd:16 2018/08/14 15:13:41 [debug] 38166#0: 4 event timer add: 16: 60000:56701215456 2018/08/14 15:13:41 [debug] 38166#0: 4 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 4 epoll add event: fd:16 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:15 ev:0001 d:00007F221C421750 2018/08/14 15:13:41 [debug] 38166#0: 3 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 3 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 3 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 3 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 3 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 572 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7B7B70:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 5 accept: 170.212.0.95:36426 fd:17 2018/08/14 15:13:41 [debug] 38166#0: 5 event timer add: 17: 60000:56701215457 2018/08/14 15:13:41 [debug] 38166#0: 5 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 5 epoll add event: fd:17 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 571 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 571 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 571 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7B73A0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 6 accept: 24.229.166.44:53837 fd:18 2018/08/14 15:13:41 [debug] 38166#0: 6 event timer add: 18: 60000:56701215457 2018/08/14 15:13:41 [debug] 38166#0: 6 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 6 epoll add event: fd:18 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 571 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:17 ev:0001 d:00007F221C421920 2018/08/14 15:13:41 [debug] 38166#0: 5 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 5 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 5 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 5 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 5 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 570 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7668A0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 7 accept: 149.173.8.9:50993 fd:19 2018/08/14 15:13:41 [debug] 38166#0: 7 event timer add: 19: 60000:56701215459 2018/08/14 15:13:41 [debug] 38166#0: 7 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 7 epoll add event: fd:19 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 all scripts loaded 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:3 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 569 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:3 ev:0004 d:00007F221C421498 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:3 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 569 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:3 ev:0001 d:00007F221C421498 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 12 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:12 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0004 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:12 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7C1B20:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 8 accept: 199.52.13.133:57562 fd:20 2018/08/14 15:13:41 [debug] 38166#0: 8 event timer add: 20: 60000:56701215460 2018/08/14 15:13:41 [debug] 38166#0: 8 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 8 epoll add event: fd:20 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:16 ev:0001 d:00007F221C421838 2018/08/14 15:13:41 [debug] 38166#0: 4 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 4 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 4 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 4 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 4 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:12 ev:0001 d:00007F221C4212C8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 14 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B7C9A70:679 2018/08/14 15:13:41 [notice] 38166#0: nchan: Redis node 192.168.220.30:6379 Discovering own slave 192.168.220.30:6379 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B7C1AC0:24 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 0 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:1 ev:80000004 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B7C1E90:104 2018/08/14 15:13:41 [debug] 38166#0: event timer add: 15: 600:56701156062 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.30:6379 node_connector_callback state 100 2018/08/14 15:13:41 [debug] 38166#0: event timer del: 14: 56701156028 2018/08/14 15:13:41 [debug] 38166#0: event timer add: 14: 240000:56701395462 2018/08/14 15:13:41 [notice] 38166#0: nchan: Redis node 192.168.220.30:6379 connected 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 2 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 1 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:22 op:1 ev:80000004 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:2 ev:00000000 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:22 ev:0004 d:00007F221C421DA8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 2 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 6 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 9 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:22 op:2 ev:00000000 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:22 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:18 ev:0001 d:00007F221C421A08 2018/08/14 15:13:41 [debug] 38166#0: 6 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 6 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 6 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 6 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 6 ssl get session: B930CEEC:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 6 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 6 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 6 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 6 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 600 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 2 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 598 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 597 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7D8DA0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 9 accept: 98.179.180.151:42182 fd:23 2018/08/14 15:13:41 [debug] 38166#0: 9 event timer add: 23: 60000:56701215465 2018/08/14 15:13:41 [debug] 38166#0: 9 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 9 epoll add event: fd:23 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 597 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:23 ev:0001 d:00007F221C421E90 2018/08/14 15:13:41 [debug] 38166#0: 9 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 9 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 9 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 9 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 9 ssl get session: AB4A61C3:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 9 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 597 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7E7C90:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 10 accept: 165.225.38.200:10175 fd:24 2018/08/14 15:13:41 [debug] 38166#0: 10 event timer add: 24: 60000:56701215466 2018/08/14 15:13:41 [debug] 38166#0: 10 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 10 epoll add event: fd:24 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 596 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7E8420:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 11 accept: 96.255.78.112:53199 fd:25 2018/08/14 15:13:41 [debug] 38166#0: 11 event timer add: 25: 60000:56701215466 2018/08/14 15:13:41 [debug] 38166#0: 11 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 11 epoll add event: fd:25 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:24 ev:0001 d:00007F221C421F78 2018/08/14 15:13:41 [debug] 38166#0: 10 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 10 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 10 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 10 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 10 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 10 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 10 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 10 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 596 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7EB280:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 12 accept: 74.70.188.198:48628 fd:26 2018/08/14 15:13:41 [debug] 38166#0: 12 event timer add: 26: 60000:56701215470 2018/08/14 15:13:41 [debug] 38166#0: 12 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 12 epoll add event: fd:26 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:20 ev:0001 d:00007F221C421BD8 2018/08/14 15:13:41 [debug] 38166#0: 8 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 8 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 8 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 8 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 8 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:25 ev:0001 d:00007F221C422060 2018/08/14 15:13:41 [debug] 38166#0: 11 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 11 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 11 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 11 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 11 ssl get session: 56543A9D:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 11 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 11 SSL ALPN supported by client: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 11 SSL ALPN selected: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 11 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 11 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 11 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:14 ev:0001 d:00007F221C421668 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL: TLSv1.2, cipher: "ECDHE-RSA-CHACHA20-POLY1305 TLSv1.2 Kx=ECDH Au=RSA Enc=CHACHA20/POLY1305(256) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 2 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 2 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 2 malloc: 000055D17B7646B0:1024 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 2 free: 000055D17B7646B0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:19 ev:0001 d:00007F221C421AF0 2018/08/14 15:13:41 [debug] 38166#0: 7 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 7 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 7 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 7 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 7 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 7 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 7 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 7 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 4 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 592 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B803990:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 13 accept: 198.103.96.11:55498 fd:27 2018/08/14 15:13:41 [debug] 38166#0: 13 event timer add: 27: 60000:56701215474 2018/08/14 15:13:41 [debug] 38166#0: 13 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 13 epoll add event: fd:27 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:26 ev:0001 d:00007F221C422148 2018/08/14 15:13:41 [debug] 38166#0: 12 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 12 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 12 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 12 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 12 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 12 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 12 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 12 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:17 ev:0001 d:00007F221C421920 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL: TLSv1.2, cipher: "ECDHE-RSA-CHACHA20-POLY1305 TLSv1.2 Kx=ECDH Au=RSA Enc=CHACHA20/POLY1305(256) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 5 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 5 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 5 malloc: 000055D17B8120D0:1024 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 5 free: 000055D17B8120D0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 4 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 588 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B8120D0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 14 accept: 129.255.1.142:50747 fd:28 2018/08/14 15:13:41 [debug] 38166#0: 14 event timer add: 28: 60000:56701215476 2018/08/14 15:13:41 [debug] 38166#0: 14 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 14 epoll add event: fd:28 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 2 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 586 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B812360:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 15 accept: 207.107.145.50:64799 fd:29 2018/08/14 15:13:41 [debug] 38166#0: 15 event timer add: 29: 60000:56701215476 2018/08/14 15:13:41 [debug] 38166#0: 15 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 15 epoll add event: fd:29 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:28 ev:0001 d:00007F221C422318 2018/08/14 15:13:41 [debug] 38166#0: 14 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 14 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 14 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 14 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 14 ssl get session: F53129EE:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 14 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 14 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 14 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 14 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 586 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B805FA0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 16 accept: 73.238.8.99:63020 fd:30 2018/08/14 15:13:41 [debug] 38166#0: 16 event timer add: 30: 60000:56701215477 2018/08/14 15:13:41 [debug] 38166#0: 16 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 16 epoll add event: fd:30 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:29 ev:0001 d:00007F221C422400 2018/08/14 15:13:41 [debug] 38166#0: 15 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 15 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 15 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 15 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 15 ssl get session: 01E6A3F8:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 15 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 15 SSL ALPN supported by client: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 15 SSL ALPN selected: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 15 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 15 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 15 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 585 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7CB320:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 17 accept: 68.32.55.246:63154 fd:31 2018/08/14 15:13:41 [debug] 38166#0: 17 event timer add: 31: 60000:56701215478 2018/08/14 15:13:41 [debug] 38166#0: 17 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 17 epoll add event: fd:31 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 584 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7CBB20:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 18 accept: 135.19.28.139:51953 fd:32 2018/08/14 15:13:41 [debug] 38166#0: 18 event timer add: 32: 60000:56701215478 2018/08/14 15:13:41 [debug] 38166#0: 18 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 18 epoll add event: fd:32 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 584 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7CBD30:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 19 accept: 65.79.147.109:59905 fd:33 2018/08/14 15:13:41 [debug] 38166#0: 19 event timer add: 33: 60000:56701215478 2018/08/14 15:13:41 [debug] 38166#0: 19 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 19 epoll add event: fd:33 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 584 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7CBF40:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 20 accept: 208.67.30.199:65515 fd:34 2018/08/14 15:13:41 [debug] 38166#0: 20 event timer add: 34: 60000:56701215478 2018/08/14 15:13:41 [debug] 38166#0: 20 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 20 epoll add event: fd:34 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 584 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B818200:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 21 accept: 81.159.150.5:58543 fd:35 2018/08/14 15:13:41 [debug] 38166#0: 21 event timer add: 35: 60000:56701215478 2018/08/14 15:13:41 [debug] 38166#0: 21 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 21 epoll add event: fd:35 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:34 ev:0001 d:00007F221C422888 2018/08/14 15:13:41 [debug] 38166#0: 20 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 20 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 20 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 20 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 20 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 20 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 20 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 20 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 0 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 584 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B8235D0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 22 accept: 100.33.47.18:61613 fd:36 2018/08/14 15:13:41 [debug] 38166#0: 22 event timer add: 36: 60000:56701215480 2018/08/14 15:13:41 [debug] 38166#0: 22 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 22 epoll add event: fd:36 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:35 ev:0001 d:00007F221C422970 2018/08/14 15:13:41 [debug] 38166#0: 21 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 21 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 21 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 21 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 21 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 21 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 21 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 21 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 10 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 all scripts loaded 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:22 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 2 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 582 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B825C30:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 23 accept: 71.81.208.231:52504 fd:37 2018/08/14 15:13:41 [debug] 38166#0: 23 event timer add: 37: 60000:56701215484 2018/08/14 15:13:41 [debug] 38166#0: 23 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 23 epoll add event: fd:37 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:30 ev:0001 d:00007F221C4224E8 2018/08/14 15:13:41 [debug] 38166#0: 16 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 16 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 16 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 16 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 16 ssl get session: 7AD37097:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 16 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 16 SSL ALPN supported by client: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 16 SSL ALPN selected: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 16 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 16 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 16 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:32 ev:0001 d:00007F221C4226B8 2018/08/14 15:13:41 [debug] 38166#0: 18 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 18 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 18 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 18 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 18 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 18 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 18 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 18 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:31 ev:0001 d:00007F221C4225D0 2018/08/14 15:13:41 [debug] 38166#0: 17 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 17 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 17 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 17 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 17 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 17 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 17 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 17 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:33 ev:0001 d:00007F221C4227A0 2018/08/14 15:13:41 [debug] 38166#0: 19 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 19 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 19 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 19 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 19 ssl get session: DA483A0D:32 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 19 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 19 SSL ALPN supported by client: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 19 SSL ALPN selected: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 19 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 19 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 19 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:22 ev:0004 d:00007F221C421DA8 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:22 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 4 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 578 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B851930:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 24 accept: 173.165.228.177:60568 fd:38 2018/08/14 15:13:41 [debug] 38166#0: 24 event timer add: 38: 60000:56701215488 2018/08/14 15:13:41 [debug] 38166#0: 24 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 24 epoll add event: fd:38 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:37 ev:0001 d:00007F221C422B40 2018/08/14 15:13:41 [debug] 38166#0: 23 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 23 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 23 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 23 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 23 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 23 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 23 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 23 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:15 ev:0001 d:00007F221C421750 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL: TLSv1.2, cipher: "ECDHE-RSA-CHACHA20-POLY1305 TLSv1.2 Kx=ECDH Au=RSA Enc=CHACHA20/POLY1305(256) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 3 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 3 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 3 malloc: 000055D17B85FF30:1024 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 3 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 3 free: 000055D17B85FF30 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:36 ev:0001 d:00007F221C422A58 2018/08/14 15:13:41 [debug] 38166#0: 22 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 22 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 22 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 22 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 22 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 22 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 22 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 22 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:14 ev:2001 d:00007F221C421668 2018/08/14 15:13:41 [debug] 38166#0: 2 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 2 malloc: 000055D17B861ED0:1024 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_read: 0 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_get_error: 5 2018/08/14 15:13:41 [debug] 38166#0: 2 peer shutdown SSL cleanly 2018/08/14 15:13:41 [info] 38166#0: 2 client closed connection while waiting for request, client: 98.113.60.241, server: 0.0.0.0:443 2018/08/14 15:13:41 [debug] 38166#0: 2 close http connection: 14 2018/08/14 15:13:41 [debug] 38166#0: 2 SSL_shutdown: 1 2018/08/14 15:13:41 [debug] 38166#0: 2 event timer del: 14: 56701215452 2018/08/14 15:13:41 [debug] 38166#0: 2 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: 2 free: 000055D17B861ED0 2018/08/14 15:13:41 [debug] 38166#0: 2 free: 000055D17B754B40, unused: 40 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 4 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 574 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B754B40:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 25 accept: 70.28.50.36:54267 fd:14 2018/08/14 15:13:41 [debug] 38166#0: 25 event timer add: 14: 60000:56701215491 2018/08/14 15:13:41 [debug] 38166#0: 25 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 25 epoll add event: fd:14 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:38 ev:0001 d:00007F221C422C28 2018/08/14 15:13:41 [debug] 38166#0: 24 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 24 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 24 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 24 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 24 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 24 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 24 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 24 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:22 ev:0001 d:00007F221C421DA8 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 12 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:21 op:3 ev:80002005 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:16 ev:0001 d:00007F221C421838 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL: TLSv1.2, cipher: "ECDHE-RSA-CHACHA20-POLY1305 TLSv1.2 Kx=ECDH Au=RSA Enc=CHACHA20/POLY1305(256) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 4 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 4 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 4 malloc: 000055D17B8630A0:1024 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 4 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 4 free: 000055D17B8630A0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:17 ev:0001 d:00007F221C421920 2018/08/14 15:13:41 [debug] 38166#0: 5 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 5 malloc: 000055D17B8630A0:1024 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_read: 835 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 5 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: 5 posix_memalign: 000055D17B7C7730:4096 @16 2018/08/14 15:13:41 [debug] 38166#0: 5 http process request line 2018/08/14 15:13:41 [debug] 38166#0: 5 http request line: "GET /nchan/sub?id=notificationsff102e9adb2b62d13a8449698eb6a5254510264a87d3d047dba7a2c06ef3034a HTTP/1.1" 2018/08/14 15:13:41 [debug] 38166#0: 5 http uri: "/nchan/sub" 2018/08/14 15:13:41 [debug] 38166#0: 5 http args: "id=notificationsff102e9adb2b62d13a8449698eb6a5254510264a87d3d047dba7a2c06ef3034a" 2018/08/14 15:13:41 [debug] 38166#0: 5 http exten: "" 2018/08/14 15:13:41 [debug] 38166#0: 5 posix_memalign: 000055D17B7C8740:4096 @16 2018/08/14 15:13:41 [debug] 38166#0: 5 http process request header line 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Host: websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Connection: Upgrade" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Pragma: no-cache" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Cache-Control: no-cache" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Upgrade: websocket" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Origin: https://www.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Sec-WebSocket-Version: 13" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Accept-Encoding: gzip, deflate, br" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Accept-Language: en-US,en;q=0.9,es;q=0.8,zh-CN;q=0.7,zh;q=0.6" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Cookie: utma=67132946.1952568325.1525527334.1525527334.1525527334.1; utmc=67132946; __utmz=67132946.1525527334.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Sec-WebSocket-Key: 8uROB5URj43Z5qy+qIR+Ag==" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header: "Sec-WebSocket-Protocol: ws+meta.nchan" 2018/08/14 15:13:41 [debug] 38166#0: 5 http header done 2018/08/14 15:13:41 [debug] 38166#0: 5 event timer del: 17: 56701215457 2018/08/14 15:13:41 [debug] 38166#0: 5 rewrite phase: 0 2018/08/14 15:13:41 [debug] 38166#0: 5 test location: "/" 2018/08/14 15:13:41 [debug] 38166#0: 5 test location: "nginx_status" 2018/08/14 15:13:41 [debug] 38166#0: 5 test location: "nchan/status" 2018/08/14 15:13:41 [debug] 38166#0: 5 test location: ~ "/nchan/pub" 2018/08/14 15:13:41 [debug] 38166#0: 5 test location: ~ "/nchan/sub" 2018/08/14 15:13:41 [debug] 38166#0: 5 using configuration "/nchan/sub" 2018/08/14 15:13:41 [debug] 38166#0: 5 http cl:-1 max:1048576 2018/08/14 15:13:41 [debug] 38166#0: 5 rewrite phase: 2 2018/08/14 15:13:41 [debug] 38166#0: 5 post rewrite phase: 3 2018/08/14 15:13:41 [debug] 38166#0: 5 generic phase: 4 2018/08/14 15:13:41 [debug] 38166#0: 5 generic phase: 5 2018/08/14 15:13:41 [debug] 38166#0: 5 access phase: 6 2018/08/14 15:13:41 [debug] 38166#0: 5 access phase: 7 2018/08/14 15:13:41 [debug] 38166#0: 5 post access phase: 8 2018/08/14 15:13:41 [debug] 38166#0: 5 generic phase: 9 2018/08/14 15:13:41 [debug] 38166#0: 5 generic phase: 10 2018/08/14 15:13:41 [debug] 38166#0: 5 http script var: "notificationsff102e9adb2b62d13a8449698eb6a5254510264a87d3d047dba7a2c06ef3034a" 2018/08/14 15:13:41 [debug] 38166#0: 5 HTTP/1.1 503 Service Temporarily Unavailable Server: nginx/1.14.0 Date: Tue, 14 Aug 2018 19:13:41 GMT Content-Length: 0 Connection: keep-alive Access-Control-Allow-Credentials: true Access-Control-Allow-Origin: https://www.ravelry.com

2018/08/14 15:13:41 [debug] 38166#0: 5 write new buf t:1 f:0 000055D17B7C8C20, pos 000055D17B7C8C20, size: 244 file: 0, size: 0 2018/08/14 15:13:41 [debug] 38166#0: 5 http write filter: l:1 f:0 s:244 2018/08/14 15:13:41 [debug] 38166#0: 5 http write filter limit 0 2018/08/14 15:13:41 [debug] 38166#0: 5 posix_memalign: 000055D17B860370:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 5 malloc: 000055D17B86B350:16384 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL buf copy: 244 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL to write: 244 2018/08/14 15:13:41 [debug] 38166#0: 5 SSL_write: 244 2018/08/14 15:13:41 [debug] 38166#0: 5 http write filter 0000000000000000 2018/08/14 15:13:41 [debug] 38166#0: 5 http finalize request: 0, "/nchan/sub?id=notificationsff102e9adb2b62d13a8449698eb6a5254510264a87d3d047dba7a2c06ef3034a" a:1, c:1 2018/08/14 15:13:41 [debug] 38166#0: 5 set http keepalive handler 2018/08/14 15:13:41 [debug] 38166#0: 5 http close request 2018/08/14 15:13:41 [debug] 38166#0: 5 http log handler 2018/08/14 15:13:41 [debug] 38166#0: 5 free: 000055D17B7C7730, unused: 48 2018/08/14 15:13:41 [debug] 38166#0: 5 free: 000055D17B7C8740, unused: 2585 2018/08/14 15:13:41 [debug] 38166#0: 5 free: 000055D17B8630A0 2018/08/14 15:13:41 [debug] 38166#0: 5 hc free: 0000000000000000 2018/08/14 15:13:41 [debug] 38166#0: 5 hc busy: 0000000000000000 0 2018/08/14 15:13:41 [debug] 38166#0: 5 free: 000055D17B86B350 2018/08/14 15:13:41 [debug] 38166#0: 5 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 5 event timer add: 17: 75000:56701230491 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 3 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 571 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B8630A0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 26 accept: 24.168.252.217:60398 fd:39 2018/08/14 15:13:41 [debug] 38166#0: 26 event timer add: 39: 60000:56701215493 2018/08/14 15:13:41 [debug] 38166#0: 26 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 26 epoll add event: fd:39 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:14 ev:0001 d:00007F221C421669 2018/08/14 15:13:41 [debug] 38166#0: 25 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 25 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 25 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 25 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 25 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 25 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 25 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 25 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0004 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: epoll del event: fd:21 op:3 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 2 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 569 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B7C88A0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 27 accept: 108.49.24.28:49856 fd:40 2018/08/14 15:13:41 [debug] 38166#0: 27 event timer add: 40: 60000:56701215494 2018/08/14 15:13:41 [debug] 38166#0: 27 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 27 epoll add event: fd:40 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:39 ev:0001 d:00007F221C422D10 2018/08/14 15:13:41 [debug] 38166#0: 26 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 26 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 26 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 26 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 26 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 26 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 26 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 26 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:20 ev:0001 d:00007F221C421BD8 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL: TLSv1.2, cipher: "ECDHE-RSA-CHACHA20-POLY1305 TLSv1.2 Kx=ECDH Au=RSA Enc=CHACHA20/POLY1305(256) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 8 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 8 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 8 malloc: 000055D17B86EAB0:1024 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 8 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 8 free: 000055D17B86EAB0 2018/08/14 15:13:41 [debug] 38166#0: timer delta: 1 2018/08/14 15:13:41 [debug] 38166#0: worker cycle 2018/08/14 15:13:41 [debug] 38166#0: epoll timer: 568 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:6 ev:0001 d:00007F221C4210F8 2018/08/14 15:13:41 [debug] 38166#0: accept on 0.0.0.0:443, ready: 0 2018/08/14 15:13:41 [debug] 38166#0: posix_memalign: 000055D17B86EAB0:512 @16 2018/08/14 15:13:41 [debug] 38166#0: 28 accept: 69.203.105.190:49353 fd:41 2018/08/14 15:13:41 [debug] 38166#0: 28 event timer add: 41: 60000:56701215495 2018/08/14 15:13:41 [debug] 38166#0: 28 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 28 epoll add event: fd:41 op:1 ev:80002001 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:40 ev:0001 d:00007F221C422DF8 2018/08/14 15:13:41 [debug] 38166#0: 27 http check ssl handshake 2018/08/14 15:13:41 [debug] 38166#0: 27 http recv(): 1 2018/08/14 15:13:41 [debug] 38166#0: 27 https ssl handshake: 0x16 2018/08/14 15:13:41 [debug] 38166#0: 27 tcp_nodelay 2018/08/14 15:13:41 [debug] 38166#0: 27 SSL server name: "websocket.ravelry.com" 2018/08/14 15:13:41 [debug] 38166#0: 27 SSL ALPN supported by client: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 27 SSL ALPN selected: http/1.1 2018/08/14 15:13:41 [debug] 38166#0: 27 SSL_do_handshake: -1 2018/08/14 15:13:41 [debug] 38166#0: 27 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 27 reusable connection: 0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:23 ev:0001 d:00007F221C421E90 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL handshake handler: 0 2018/08/14 15:13:41 [debug] 38166#0: shmtx lock 2018/08/14 15:13:41 [debug] 38166#0: slab alloc: 166 slot: 5 2018/08/14 15:13:41 [debug] 38166#0: slab alloc: 00007F223D298000 2018/08/14 15:13:41 [debug] 38166#0: slab alloc: 128 slot: 4 2018/08/14 15:13:41 [debug] 38166#0: slab alloc: 00007F223D296080 2018/08/14 15:13:41 [debug] 38166#0: 9 ssl new session: 7970A85D:32:166 2018/08/14 15:13:41 [debug] 38166#0: shmtx unlock 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL_do_handshake: 1 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD" 2018/08/14 15:13:41 [debug] 38166#0: 9 reusable connection: 1 2018/08/14 15:13:41 [debug] 38166#0: 9 http wait request handler 2018/08/14 15:13:41 [debug] 38166#0: 9 malloc: 000055D17B7EB5D0:1024 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL_read: -1 2018/08/14 15:13:41 [debug] 38166#0: 9 SSL_get_error: 2 2018/08/14 15:13:41 [debug] 38166#0: 9 free: 000055D17B7EB5D0 2018/08/14 15:13:41 [debug] 38166#0: epoll: fd:21 ev:0001 d:00007F221C421CC0 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.140:6379 node_connector_callback state 14 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B7DCD90:679 2018/08/14 15:13:41 [notice] 38166#0: nchan: Redis node 192.168.220.140:6379 Discovering own master 192.168.220.140:6379 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B802E60:24 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node 192.168.220.190:6379 node_connector_callback state 0 2018/08/14 15:13:41 [debug] 38166#0: epoll add event: fd:42 op:1 ev:80000004 2018/08/14 15:13:41 [debug] 38166#0: malloc: 000055D17B7E78C0:104 2018/08/14 15:13:41 [debug] 38166#0: event timer add: 15: 600:56701156095 2018/08/14 15:13:41 [debug] 38166#0: nchan: Redis node :0 node_connector_callback state 100 2018/08/14 15:13:43 [notice] 38165#0: signal 17 (SIGCHLD) received from 38166 2018/08/14 15:13:43 [alert] 38165#0: worker process 38166 exited on signal 11 (core dumped)

outcassed commented 6 years ago

Sorry I didn't mention that my Redis master has a read only replica.

I see that it is discovering it...

outcassed commented 6 years ago

Also, it is connecting to a single Redis through a load balancer (haproxy) so the IP address in the nginx configuration is different from what the master thinks its IP address is.

outcassed commented 6 years ago

I don't get the crash if I use the Redis server's IP address instead of the load balancer (haproxy) IP.

outcassed commented 6 years ago

While I'm here:

The new "auto-discover and use Redis slaves to balance PUBSUB traffic." is very cool but it's sort of surprising default behavior?

slact commented 6 years ago

Yeah, using Redis via a load-balancer is definitely not supported, because Nchan expects the IP&port to map to the same server while connecting. It shouldn't crash when connecting through HAproxy though, I'll fix that.

As for using slaves for load-balancing, i don't think this is unusual default behavior, considering how Nchan had already automatically detected clusters and load-balanced between shards.

slact commented 6 years ago

I've added some connection logic to detect this scenario. Could you rebuild from master and try connecting via HAproxy again? You should get a failure to connect in the error log with the message, "IP address connects to more than one server. Is Redis behind a proxy?"

outcassed commented 6 years ago

ok I'll test that out.

On the subject of autodiscover: if I don't want nchan to talk to my replicas for whatever reason, would this setting do the trick?

nchan_redis_subscribe_weights master=1 slave=0;

slact commented 5 years ago

if I don't want nchan to talk to my replicas for whatever reason, would this setting do the trick? nchan_redis_subscribe_weights master=1 slave=0;

No, Redis now talks to all reachable masters and slaves. nchan_redis_subscribe_weights just means that the slaves won't be used for anything. That is, unless they get promoted to masters.

thrillertom commented 5 years ago

hi @slact,

About the autodiscover feature, do we have any chance to make it configurable? I mean if we can set replica IP by conf files? The default behavior could not get the right IP in a complex network environment. e.g. aws elasticache

slact commented 5 years ago

@thrillertom what version of Nchan are you using? I have made several tweaks over time to support autodiscovering servers on Elasticache.

thrillertom commented 5 years ago

@slact we use 1.2.3, could you please show me the way? I didn't find related configuration on https://nchan.io

slact commented 5 years ago

@thrillertom there's nothing you need to do explicitly. Nchan may fail to connect to the autodiscovered internal ips of slaves, but will connect after retrying. If that's not what is happening for you, please open a separate ticket and we'll investigate the issue.