Commands timeout - Githubissues

ammgws commented 7 years ago

Seems to have started after a new user logged in and issued a command.
Gunicorn seems to reboot worker before it gets to the response = socket.recv() line.
Gunicorn worker timeout currently set to 30seconds.
Either serialmanager thread is dead/taking too long or the request is just taking too long
Serialmanager log stops at 18:00 so seems like it has died...

gunicorn log:

[2017-03-03 17:41:39 +0900] [1099] [DEBUG] GET /
[2017-03-03 17:59:12 +0900] [1099] [DEBUG] GET /login
[2017-03-03 17:59:18 +0900] [1099] [DEBUG] GET /authorize/google
[2017-03-03 17:59:18 +0900] [1099] [DEBUG] GET /callback/google
[2017-03-03 17:59:22 +0900] [1099] [DEBUG] GET /
[2017-03-03 17:59:29 +0900] [1099] [DEBUG] GET /command
[2017-03-03 17:59:59 +0900] [474] [CRITICAL] WORKER TIMEOUT (pid:1099)
[2017-03-03 18:00:00 +0900] [1099] [INFO] Worker exiting (pid: 1099)
[2017-03-03 18:00:01 +0900] [3861] [INFO] Booting worker with pid: 3861
[2017-03-03 18:00:02 +0900] [3861] [DEBUG] GET /command
[2017-03-03 18:00:32 +0900] [474] [CRITICAL] WORKER TIMEOUT (pid:3861)
[2017-03-03 18:00:32 +0900] [3861] [INFO] Worker exiting (pid: 3861)
[2017-03-03 18:00:33 +0900] [3884] [INFO] Booting worker with pid: 3884
[2017-03-03 18:00:33 +0900] [3884] [DEBUG] GET /command
[2017-03-03 18:01:04 +0900] [474] [CRITICAL] WORKER TIMEOUT (pid:3884)

flask log:

2017-03-03 15:02:47.413 ammcon_frontend INFO     Command "living1 off" received. Sending message: b'\xb4\x00' (views.py:146)
2017-03-03 15:02:47.427 ammcon_frontend INFO     ############### Connected to zeroMQ server ############### (views.py:154)
2017-03-03 15:02:47.539 ammcon_frontend INFO     Response received: ['0x3c', '0x6', '0xb4', '0x0', '0xff', '0xc1', '0x3e'] (views.py:171)
2017-03-03 15:02:47.545 ammcon_frontend INFO     Finished handling command request. (views.py:198)
2017-03-03 17:59:22.108 ammcon_frontend DEBUG    static/httpslh3googleusercontentcom-oxxxxExxAAAAxxxIAAAAAxxxmMlTodE-xxxcphotojpg.jpg (oauth.py:103)
2017-03-03 17:59:22.575 ammcon_frontend INFO     Created user for xxxx@gmail.com with role [end-user]. (oauth.py:73)
2017-03-03 17:59:22.796 ammcon_frontend DEBUG    Saved user xxxx@gmail.com to database. (oauth.py:84)
2017-03-03 17:59:29.447 ammcon_frontend INFO     Command "living1 night" received. Sending message: b'\xb4\x05' (views.py:146)
2017-03-03 17:59:29.501 ammcon_frontend INFO     ############### Connected to zeroMQ server ############### (views.py:154)
2017-03-03 17:59:29.507 ammcon_frontend DEBUG    yarpliving1 night0 (views.py:164)
2017-03-03 17:59:29.539 ammcon_frontend DEBUG    yarpliving1 night1 (views.py:164)
2017-03-03 18:00:02.572 ammcon_frontend DEBUG    This is before first request (views.py:304)
2017-03-03 18:00:08.752 ammcon_frontend INFO     Command "living2 night" received. Sending message: b'\xb5\x05' (views.py:146)
2017-03-03 18:00:08.795 ammcon_frontend INFO     ############### Connected to zeroMQ server ############### (views.py:154)
2017-03-03 18:00:09.068 ammcon_frontend DEBUG    yarpliving2 night0 (views.py:164)
2017-03-03 18:00:34.080 ammcon_frontend DEBUG    This is before first request (views.py:304)

serial manager log:

2017-03-03 17:58:59,666 root         DEBUG    Received command in queue: b'\xd1' (serialmanager.py:56)
2017-03-03 17:58:59,673 root         DEBUG    yarptemp0 (templogger.py:49)
2017-03-03 17:58:59,678 root         DEBUG    yarptemp1 (templogger.py:49)
2017-03-03 17:58:59,688 root         DEBUG    Requesting temperature. (templogger.py:52)
2017-03-03 17:58:59,685 root         INFO     Command sent to microcontroller: ['0x3c', '0xd1', '0xa7', '0x3e'] (serialmanager.py:284)
2017-03-03 17:59:00,165 root         DEBUG    Raw response: ['0x3c', '0x6', '0xd1', '0xa7', '0x13', '0x0', '0x25', '0x0', '0x8a', '0x3e'] (serialmanager.py:66)
2017-03-03 17:59:00,170 root         DEBUG    Destuffed   : ['0x3c', '0x6', '0xd1', '0xa7', '0x13', '0x0', '0x25', '0x0', '0x8a', '0x3e'] (serialmanager.py:74)
2017-03-03 17:59:00,196 root         DEBUG    Received    : ['0x3c', '0x6', '0xd1', '0xa7', '0x13', '0x0', '0x25', '0x0', '0x8a', '0x3e'] (templogger.py:54)
2017-03-03 17:59:29,552 root         DEBUG    Received command in queue: b'\xb4\x05' (serialmanager.py:56)
2017-03-03 17:59:29,572 root         INFO     Command sent to microcontroller: ['0x3c', '0xb4', '0x5', '0x7c', '0x3e'] (serialmanager.py:284)
2017-03-03 18:00:00,381 root         DEBUG    Requesting temperature. (templogger.py:52)

ammgws commented 7 years ago

Happened again even on the latest version. Second time it's happened, both times are when a secondary account accessed the page and ran a command (coincidence?). Serial manager thread seems to be the culprit as the temp logger stops logging.

gunicorn log:

[2017-03-14 17:50:58 +0900] [6195] [DEBUG] GET /
[2017-03-14 17:51:03 +0900] [6195] [DEBUG] GET /data/1
[2017-03-14 17:51:05 +0900] [6195] [DEBUG] GET /data/2
[2017-03-14 17:51:05 +0900] [6195] [DEBUG] GET /data/3
[2017-03-14 17:51:11 +0900] [6195] [DEBUG] GET /command
[2017-03-14 17:51:42 +0900] [6044] [CRITICAL] WORKER TIMEOUT (pid:6195)
[2017-03-14 17:51:42 +0900] [6195] [INFO] Worker exiting (pid: 6195)
[2017-03-14 17:51:44 +0900] [19647] [INFO] Booting worker with pid: 19647
[2017-03-14 17:51:44 +0900] [19647] [DEBUG] GET /command
[2017-03-14 17:52:15 +0900] [6044] [CRITICAL] WORKER TIMEOUT (pid:19647)
[2017-03-14 17:52:15 +0900] [19647] [INFO] Worker exiting (pid: 19647)
[2017-03-14 17:52:16 +0900] [19663] [INFO] Booting worker with pid: 19663

flask log:

2017-03-14 00:15:39.239 ammcon_frontend INFO     Finished handling command request. (views.py:193)
2017-03-14 17:51:12.245 ammcon_frontend INFO     Command "living1 night" received. Sending message: b'\xb4\x05' (views.py:141)
2017-03-14 17:51:12.288 ammcon_frontend INFO     Connected to zeroMQ server. (views.py:149)
2017-03-14 17:51:45.121 ammcon_frontend DEBUG    This is before first request (views.py:299)
2017-03-14 17:51:47.401 ammcon_frontend INFO     Command "living2 night" received. Sending message: b'\xb5\x05' (views.py:141)
2017-03-14 17:51:47.440 ammcon_frontend INFO     Connected to zeroMQ server. (views.py:149)
2017-03-14 17:51:47.678 ammcon_frontend DEBUG    yarpliving2 night0 (views.py:159)
2017-03-14 17:51:47.683 ammcon_frontend DEBUG    yarpliving2 night1 (views.py:159)
2017-03-14 17:51:47.688 ammcon_frontend DEBUG    yarpliving2 night2 (views.py:159)
2017-03-14 19:23:01.202 ammcon_frontend DEBUG    This is before first request (views.py:299)

serial manager:

2017-03-14 17:50:24,112 root         DEBUG    Received command in queue: b'\xd1' (serialmanager.py:56)
2017-03-14 17:50:24,120 root         DEBUG    yarptemp0 (templogger.py:49)
2017-03-14 17:50:24,124 root         DEBUG    yarptemp1 (templogger.py:49)
2017-03-14 17:50:24,134 root         DEBUG    Requesting temperature. (templogger.py:52)
2017-03-14 17:50:24,131 root         INFO     Command sent to microcontroller: ['0x3c', '0xd1', '0xa7', '0x3e'] (serialmanager.py:284)
2017-03-14 17:50:24,610 root         DEBUG    Raw response: ['0x3c', '0x6', '0xd1', '0xa7', '0x14', '0x32', '0x24', '0x0', '0x87', '0x3e'] (serialmanager.py:66)
2017-03-14 17:50:24,615 root         DEBUG    Destuffed   : ['0x3c', '0x6', '0xd1', '0xa7', '0x14', '0x32', '0x24', '0x0', '0x87', '0x3e'] (serialmanager.py:74)
2017-03-14 17:50:24,623 root         DEBUG    Received    : ['0x3c', '0x6', '0xd1', '0xa7', '0x14', '0x32', '0x24', '0x0', '0x87', '0x3e'] (templogger.py:54)
2017-03-14 17:51:12,310 root         DEBUG    Received command in queue: b'\xb4\x05' (serialmanager.py:56)
2017-03-14 17:51:12,321 root         INFO     Command sent to microcontroller: ['0x3c', '0xb4', '0x5', '0x7c', '0x3e'] (serialmanager.py:284)
2017-03-14 17:51:24,781 root         DEBUG    Requesting temperature. (templogger.py:52)

ammgws commented 7 years ago

Able to reproduce in production but not development (aka virtual serial port):

Start up ammcon & ammcon-frontend
Send the living1 night command through the web GUI
Fail. GET https://****.com:*****/command?command=living1+night 502 (Bad Gateway)

ammgws commented 7 years ago

Commands that cause system to fail (all other commands respond normally):

1. "living1 night" command

living1 night (b'\xB4\x05')
Command sent to microcontroller: ['0x3c', '0xb4', '0x5', '0x7c', '0x3e'] (serialmanager.py:284)

CRC equates to 0x7c, which is the byte used for escaping with AmmCon's current serial framing method. Thus the CRC should be escaped before sending, but clearly serialmanager.py is not doing this.
Plugged in ammcon hardware to dev PC and noted that it doesn't respond at all to
0x3CB4057C3E but it does to 0x3CB4057C7C3E. This is because it prematurely reaches the end flag byte (0x3e) as it thinks it is part of the response payload.

Countermeasure

Modified serialmanager.py so that it stuffs CRC byte before sending: Command sent to microcontroller: ['0x3c', '0xb4', '0x5', '0x7c', '0x7c', '0x3e'] (serialmanager.py:286)
Sent: 0x3CB4057C7C3E, Response: 0x3C06B405FA743E (valid command response - correct behavior)
Sent: 0x3CB4057C553E, Response: 0x3C15B40511FF3E (invalid CRC response - correct behavior) → FIXED

While the problem above is fixed, need to also check the following at a later time:

Check if ammcon hardware code can deal with escaped escape bytes (need to add FROM_ESC state to the state machine used when reading in commands?)
Check if need to modify serialmanager.py destuffing function to deal with escaped escape bytes

2. Aircon 'AC' commands

living AC off (b'\xAC\x00')
Command sent to microcontroller: ['0x3c', '0xac', '0x0', '0xa3', '0x3e'] (serialmanager.py:284)

living AC auto (b'\xAC\x01')
Command sent to microcontroller: ['0x3c', '0xac', '0x1', '0x44', '0x3e'] (serialmanager.py:284)

Plugged in ammcon hardware to dev PC and noted that it does not respond to 0x3CAC00A33E, but does respond to 0x3CAC00553E with invalid CRC response (changed CRC byte to random value for testing)
Reason is that the aircon commands were removed from the hardware code and the function wasn't updated to return an error/NAK or any other response in place of it. It responds to the command with the invalid CRC because it reaches a different code block.
```
    /* Aircon commands */
    case 0xAC:
      /* removed for now */
      break;
```
Countermeasure Removed the case statement from ammcon hardware code:
Sent: 0x3CAC00A33E, Response: 0x3C15AC0098713E (unknown command response - correct behavior)
Sent: 0x3CAC00553E, Response: 0x3C15AC0011FF3E (invalid CRC response - correct behavior) → FIXED

ammgws commented 7 years ago

Fixed by ammcon commit 4ec8a8b869e4dc7479b36b3159bf41c66dbb7b57

ammgws / ammcon-frontend

Commands timeout #15