Logged results below the dashed line are relevant to the test.
Lines above it were logged after purging all logs and then running supervisorctl restart all
.
[2020-08-24 18:40:14 +0200] [1306] [INFO] Starting gunicorn 19.10.0
[2020-08-24 18:40:14 +0200] [1306] [INFO] Listening at: http://127.0.0.1:8000 (1306)
[2020-08-24 18:40:14 +0200] [1306] [INFO] Using worker: sync
/home/erpdev/frappe-bench-EELS/env/lib/python3.8/os.py:1023: RuntimeWarning: line buffering (buffering=1) isn't supported in binary mode, the default buffer size will be used
return io.open(fd, *args, **kwargs)
[2020-08-24 18:40:14 +0200] [1348] [INFO] Booting worker with pid: 1348
< mark before test >
--------------------
/home/erpdev/frappe-bench-EELS/env/lib/python3.8/os.py:1023: RuntimeWarning: line buffering (buffering=1) isn't supported in binary mode, the default buffer size will be used
return io.open(fd, *args, **kwargs)
[2020-08-24 18:44:42 +0200] [1306] [CRITICAL] WORKER TIMEOUT (pid:1348)
[2020-08-24 18:44:42 +0200] [1348] [INFO] Worker exiting (pid: 1348)
[2020-08-24 18:44:43 +0200] [1389] [INFO] Booting worker with pid: 1389
Here you can see that NodeJs closed the connection after waiting for ERPNext for 2 minutes…
Traceback (most recent call last):
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 665, in urlopen
httplib_response = self._make_request(
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 421, in _make_request
six.raise_from(e, None)
File "<string>", line 3, in raise_from
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 416, in _make_request
httplib_response = conn.getresponse()
File "/usr/lib/python3.8/http/client.py", line 1332, in getresponse
response.begin()
File "/usr/lib/python3.8/http/client.py", line 303, in begin
version, status, reason = self._read_status()
File "/usr/lib/python3.8/http/client.py", line 272, in _read_status
raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/adapters.py", line 439, in send
resp = conn.urlopen(
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 719, in urlopen
retries = retries.increment(
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/util/retry.py", line 400, in increment
raise six.reraise(type(error), error, _stacktrace)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/packages/six.py", line 734, in reraise
raise value.with_traceback(tb)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 665, in urlopen
httplib_response = self._make_request(
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 421, in _make_request
six.raise_from(e, None)
File "<string>", line 3, in raise_from
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/urllib3/connectionpool.py", line 416, in _make_request
httplib_response = conn.getresponse()
File "/usr/lib/python3.8/http/client.py", line 1332, in getresponse
response.begin()
File "/usr/lib/python3.8/http/client.py", line 303, in begin
version, status, reason = self._read_status()
File "/usr/lib/python3.8/http/client.py", line 272, in _read_status
raise RemoteDisconnected("Remote end closed connection without"
urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/erpdev/frappe-bench-EELS/apps/frappe/frappe/app.py", line 64, in application
response = frappe.api.handle()
File "/home/erpdev/frappe-bench-EELS/apps/frappe/frappe/api.py", line 58, in handle
return frappe.handler.handle()
File "/home/erpdev/frappe-bench-EELS/apps/frappe/frappe/handler.py", line 30, in handle
data = execute_cmd(cmd)
File "/home/erpdev/frappe-bench-EELS/apps/frappe/frappe/handler.py", line 69, in execute_cmd
return frappe.call(method, **frappe.form_dict)
File "/home/erpdev/frappe-bench-EELS/apps/frappe/frappe/__init__.py", line 1086, in call
return fn(*args, **newargs)
File "/home/erpdev/frappe-bench-EELS/apps/erpnext/erpnext/accounts/doctype/sales_invoice/sales_invoice.py", line 1706, in electronic_invoice
response = requests.post(url, data = payload, headers={"Content-Type": "application/json"})
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/api.py", line 119, in post
return request('post', url, data=data, json=json, **kwargs)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/api.py", line 61, in request
return session.request(method=method, url=url, **kwargs)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/sessions.py", line 530, in request
resp = self.send(prep, **send_kwargs)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/sessions.py", line 643, in send
r = adapter.send(request, **kwargs)
File "/home/erpdev/frappe-bench-EELS/env/lib/python3.8/site-packages/requests/adapters.py", line 498, in send
raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))
Log directory before test:
total 48
drwxr-xr-x 2 erpdev erpdev 4096 Aug 24 18:40 ./
drwxr-xr-x 7 erpdev erpdev 4096 Aug 24 18:20 ../
-rw-r--r-- 1 erpdev erpdev 273 Aug 24 18:40 bench.log
-rw-r--r-- 1 erpdev erpdev 192 Aug 24 18:40 frappe.log
-rw-r--r-- 1 erpdev erpdev 370 Aug 24 18:40 frappe.web.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 node-socketio.error.log
-rw-r--r-- 1 erpdev erpdev 76 Aug 24 18:40 node-socketio.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-cache.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-cache.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-queue.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-queue.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-socketio.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-socketio.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 schedule.error.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 schedule.log
-rw-r--r-- 1 erpdev erpdev 2693 Aug 24 18:40 scheduler.log
-rw-r--r-- 1 erpdev erpdev 499 Aug 24 18:40 web.error.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 web.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 worker.error.log
-rw-r--r-- 1 erpdev erpdev 543 Aug 24 18:40 worker.log
Log directory after test:
total 84
drwxr-xr-x 2 erpdev erpdev 4096 Aug 24 18:40 ./
drwxr-xr-x 7 erpdev erpdev 4096 Aug 24 18:20 ../
-rw-r--r-- 1 erpdev erpdev 273 Aug 24 18:40 bench.log
-rw-r--r-- 1 erpdev erpdev 1535 Aug 24 18:42 frappe.log
-rw-r--r-- 1 erpdev erpdev 10654 Aug 24 18:44 frappe.web.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 node-socketio.error.log
-rw-r--r-- 1 erpdev erpdev 76 Aug 24 18:40 node-socketio.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-cache.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-cache.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-queue.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-queue.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 redis-socketio.error.log
-rw-r--r-- 1 erpdev erpdev 1241 Aug 24 18:40 redis-socketio.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 schedule.error.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 schedule.log
-rw-r--r-- 1 erpdev erpdev 9666 Aug 24 18:49 scheduler.log
-rw-r--r-- 1 erpdev erpdev 967 Aug 24 18:44 web.error.log
-rw-r--r-- 1 erpdev erpdev 4616 Aug 24 18:44 web.log
-rw-r--r-- 1 erpdev erpdev 0 Aug 24 18:40 worker.error.log
-rw-r--r-- 1 erpdev erpdev 12639 Aug 24 18:48 worker.log
So the modified files are:
- frappe.log
- frappe.web.log
- scheduler.log
- web.error.log
- web.log
- worker.log
3 & 6 :: scheduler.log and worker.log show what they always show, unchanged.
2 :: frappe.web.log shows page loads
1 :: frappe.log shows my INFO log line just prior to the call to NodeJS
2020-08-24 18:42:42,833 INFO frappe Ready to call NodeJs with payload :: { "invoiceId": "001-002-000002780", "access_key": "2707202001179217775800110010020000027801234567813" }; URL http://erp.erpnext.host:5500/mail
Site: erp.erpnext.host
Form Dict: {'invoice_id': '001-002-000002780', 'command': 'mail', 'cmd': 'erpnext.accounts.doctype.sales_invoice.sales_invoice.custom_stuff'}
My logging from NodeJS shows execution held on call back to ERPNext:
const options = { headers: { Authorization: `token ${process.env.ERPNEXT_TOKN}` } };
let rslt = {};
const urlInvoice = `${env.REST_SVC}/${env.INVOICE}/${invoiceId}`;
try {
console.log(`GETTING INVOICE :: '${urlInvoice}'. tkn: ${process.env.ERPNEXT_TOKN}`);
rslt = await axios.get(urlInvoice, options);
console.log('GOT INVOICE');
} catch (error) {
msg = `ERROR when getting invoice #${invoiceId}:\n ${JSON.stringify(error, null, 2)}`;
console.error(msg);
}
When running from bench start
there is no perceptible delay between
GETTING INVOICE :: 'http://erp.erpnext.host:8000/api/resource/Sales Invoice/001-002-000002780'. tkn: c26.........bfe:bd8........a074
POST /mail - - ms - -
GOT INVOICE
Through all of that I found only two bits of useful information:
- The actual timeout happens with
[CRITICAL] WORKER TIMEOUT (pid:1348)
- The last action before freeze up is NodeJs calling into ERPNext API