postmortem KennyBot 2017-06-26

postmortem-kennybot-20170626.md

Movie API call

Mon Jun 26 2017 17:39:19 GMT+0200 (CEST) urlCurrent: 1 , fetchUrl: http://www.omdbapi.com/?apikey=XXXXXX&t=wizard&y=1978  

Start of event
no websocket event received for the message that was posted
error log
websocket not alive for 70 seconds
websocket not alive for 140 seconds
websocket not alive for 210 seconds
ws not alive
Missed from TS

attempt reconnect of websocket

ws re-init  
websocket retry post events { events:  
   [ { event_type: 1,  
       time_stamp: 1498491660,  
       content: '!!status',  
       user_id: 152859,  
       user_name: 'Shadow Wizard',  
       room_id: 721,  
       message_id: 6133223 } ],  
  time: 13960971,  
  sync: 1498491668,
  ms: 1 }
ws restarted
wss://chat.sockets.stackexchange.com/events/721/xxxxxxxxxxxxxxxxx?l=13960971
websocket created
ws open for 721

Missed from TS
at this moment Kenny missed the !!status command

message:  {"r721":{},"r1034":{}}
message:  {"r721":{"e":[{"event_type":1,"time_stamp":1498491695,"content":"and is !!status rate limited for whole day?","id":13960976,"user_id":152859,"user_name":"Shadow Wizard","room_id":721,"room_name":"Shadow\u0027s Den","message_id":6133229}],"t":13960978,"d":3},"r1034":{"t":13960978,"d":3}}
message:  {"r721":{},"r1034":{}}
message:  {"r721":{"e":[{"event_type":1,"time_stamp":1498491710,"content":"it\u0026#39;s over three hours since last status check...","id":13960982,"user_id":152859,"user_name":"Shadow Wizard","room_id":721,"room_name":"Shadow\u0027s Den","message_id":6133234}],"t":13960982,"d":1},"r1034":{"t":13960982,"d":1}}
message:  {"r721":{},"r1034":{}}

error log

websocket not alive for 70 seconds
websocket not alive for 140 seconds
websocket not alive for 210 seconds

ws not alive

Missed
Missed
Missed
Missed
Missed
Missed

ws re-init
websocket retry post events { events:
   [ { event_type: 1,
       time_stamp: 1498491826,
       content: 'Good thing I made it immortal ;D',
       user_id: 229438,
       user_name: 'ProgramFOX',
       room_id: 721,
       message_id: 6133260 } ],
  time: 13961049,
  sync: 1498491949,
  ms: 2 }
ws restarted
wss://chat.sockets.stackexchange.com/events/721/xxxxxxxxxxxxxxx?l=13961049
websocket created
ws open for 721
message:  {"r721":{"t":13961050,"d":1},"r1034":{"t":13961050,"d":1}}
message:  {"r721":{},"r1034":{}}

Conclusion

The websocket recovery works.
From the log we learn there is no websocket close event fired. Technically the TCP/IP websocket is still available.
The missing heartbeats (aka {"r721":{},"r1034":{}}) prove otherwise.
What might need improvement is the time it takes to be 100% sure the socket died. After 90 seconds we can be sure as there should be an event every 30 seconds.

Once the webocket is reconnected, it would be nice the bot used postEvents to get any messages it might have missed while it was reconnecting