Setup Wizard fails with "Request Timed Out ( Could not start up: Error in setup )"

I would grateful for any hints about what could be causing this, or how to debug it :

This is from frappe-bench/logs/web.error.log :

[2020-02-11 21:42:15 -0500] [31871] [CRITICAL] WORKER TIMEOUT (pid:31894)
[2020-02-11 21:42:15 -0500] [31894] [ERROR] Error handling request /api/method/frappe.desk.page.setup_wizard.setup_wizard.setup_complete
Traceback (most recent call last):
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/app.py", line 60, in application
   response = frappe.api.handle()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/api.py", line 55, in handle
   return frappe.handler.handle()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/handler.py", line 22, in handle
   data = execute_cmd(cmd)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/handler.py", line 61, in execute_cmd
   return frappe.call(method, **frappe.form_dict)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/__init__.py", line 1042, in call
   return fn(*args, **newargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/desk/page/setup_wizard/setup_wizard.py", line 71, in setup_complete
   task.get('fn')(task.get('args'))
 File "/home/erpnext/frappe-bench/apps/erpnext/erpnext/setup/setup_wizard/setup_wizard.py", line 101, in setup_defaults
   fixtures.install_defaults(frappe._dict(args))
 File "/home/erpnext/frappe-bench/apps/erpnext/erpnext/setup/setup_wizard/operations/install_fixtures.py", line 442, in install_defaults
   global_defaults.save()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 272, in save
   return self._save(*args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 325, in _save
   self.run_post_save_methods()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 919, in run_post_save_methods
   self.run_method("on_update")
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 787, in run_method
   out = Document.hook(fn)(self, *args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 1058, in composer
   return composed(self, method, *args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 1041, in runner
   add_to_return_value(self, fn(self, *args, **kwargs))
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 781, in <lambda>
   fn = lambda self, *args, **kwargs: getattr(self, method)(*args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/erpnext/erpnext/setup/doctype/global_defaults/global_defaults.py", line 47, in on_update
   self.toggle_rounded_total()
 File "/home/erpnext/frappe-bench/apps/erpnext/erpnext/setup/doctype/global_defaults/global_defaults.py", line 66, in toggle_rounded_total
   make_property_setter(doctype, "rounded_total", "print_hide", self.disable_rounded_total, "Check")
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/custom/doctype/property_setter/property_setter.py", line 90, in make_property_setter
   property_setter.insert()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 259, in insert
   self.run_post_save_methods()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 919, in run_post_save_methods
   self.run_method("on_update")
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 787, in run_method
   out = Document.hook(fn)(self, *args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 1058, in composer
   return composed(self, method, *args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 1041, in runner
   add_to_return_value(self, fn(self, *args, **kwargs))
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 781, in <lambda>
   fn = lambda self, *args, **kwargs: getattr(self, method)(*args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/custom/doctype/property_setter/property_setter.py", line 74, in on_update
   validate_fields_for_doctype(self.doc_type)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/core/doctype/doctype/doctype.py", line 667, in validate_fields_for_doctype
   doc = frappe.get_doc("DocType", doctype)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/__init__.py", line 740, in get_doc
   doc = frappe.model.document.get_doc(*args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 70, in get_doc
   return controller(*args, **kwargs)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 105, in __init__
   self.load_from_db()
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/model/document.py", line 161, in load_from_db
   "*", as_dict=True, order_by="idx asc")
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/database/database.py", line 445, in get_values
   out = self._get_values_from_table(fields, filters, doctype, as_dict, debug, order_by, update)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/database/database.py", line 592, in _get_values_from_table
   as_dict=as_dict, debug=debug, update=update)
 File "/home/erpnext/frappe-bench/apps/frappe/frappe/database/database.py", line 156, in sql
   self._cursor.execute(query, values)
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
   result = self._query(query)
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
   conn.query(q)
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 517, in query
   self._affected_rows = self._read_query_result(unbuffered=unbuffered)
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 732, in _read_query_result
   result.read()
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 1082, in read
   self._read_result_packet(first_packet)
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 1152, in _read_result_packet
   self._read_rowdata_packet()
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 1190, in _read_rowdata_packet
   rows.append(self._read_row_from_packet(packet))
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 1199, in _read_row_from_packet
   data = packet.read_length_coded_string()
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/protocol.py", line 175, in read_length_coded_string
   length = self.read_length_encoded_integer()
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/protocol.py", line 156, in read_length_encoded_integer
   c = self.read_uint8()
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/protocol.py", line 119, in read_uint8
   self._position += 1
 File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/gunicorn/workers/base.py", line 201, in handle_abort
   sys.exit(1)
SystemExit: 1
During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle
    self.handle_request(listener, req, client, addr)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/werkzeug/local.py", line 231, in application
    return ClosingIterator(app(environ, start_response), self.cleanup)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/werkzeug/wrappers/base_request.py", line 237, in application
    resp = f(*args[:-2] + (request,))
  File "/home/erpnext/frappe-bench/apps/frappe/frappe/app.py", line 88, in application
    frappe.db.rollback()
  File "/home/erpnext/frappe-bench/apps/frappe/frappe/database/database.py", line 753, in rollback
    self.sql("rollback")
  File "/home/erpnext/frappe-bench/apps/frappe/frappe/database/database.py", line 171, in sql
    self._cursor.execute(query)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
    result = self._query(query)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
    conn.query(q)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 517, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 732, in _read_query_result
    result.read()
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 1075, in read
    first_packet = self.connection._read_packet()
  File "/home/erpnext/frappe-bench/env/lib/python3.6/site-packages/pymysql/connections.py", line 671, in _read_packet
    % (packet_number, self._next_seq_id))
pymysql.err.InternalError: Packet sequence number wrong - got 186 expected 1
[2020-02-11 21:42:15 -0500] [31894] [INFO] Worker exiting (pid: 31894)
[2020-02-11 21:42:15 -0500] [31967] [INFO] Booting worker with pid: 31967

It occurs during the set up wizard when it gets to “setting default values”.

Running on Ubuntu 18.04

me@mine:~/frappe-bench$ bench version
erpnext 12.4.3
frappe 12.2.1
me@mine:~/frappe-bench$ 

Update 2020/02/12 08:50 EST

I took a full database backup before running the wizard and a second backup after.

Comparing the two I found that tabSingles contains all the data points entered in the wizard.

In short, this is clearly a bug in the way the setup wizard is writing the “rounded_total” setting, not something to do with MariaDb installation.

I searched the backup text and found two instances of the word rounded :

('HR Settings','disable_rounded_total','0')
('Global Defaults','disable_rounded_total','0')

I surmise that toggle_rounded_total in global_defaults.py is not finding a required dependency in the database,

Update 2020/02/12 09:30 EST

The domain settings I chose were :

  • Manufacturing
  • Distribution
  • Retail
  • Services

I tried again with only Retail and then again with only Manufacturing but that’s not going to be a work around.

What I did see is that “rounded_total” isn’t always the setting that causes the crash :

I saw …

make_property_setter(doctype, "in_words", "hidden", self.disable_in_words, "Check")

…

make_property_setter(doctype, "base_rounded_total", "hidden", self.disable_rounded_total, "Check")

… are also involved.

Update 2020/02/12 14:00 EST

Still trying to crack this.

I pulled v12.4.2, decompressed it into frappe-bench/apps and ran bench migrate.

bench version shows 12.4.2, but the error persists.

Update 2020/02/14 09:30 EST

NONE OF MY UPDATES ABOVE ARE RELEVANT!

THE REAL PROBLEM IS IN THE FIRST LINE…

[CRITICAL] WORKER TIMEOUT (pid:31894)

The detailed stack trace is no help at all. It shows what was executing when the worker timed out, but that varies widely from incident to incident.

1 Like

facing the same issue. Where u able to fix this?

No. It’s really exasperating. These getting started problems just never seem to end.

Can you post about your setup and what you have tried so far, please?

1 Like

Have the same issue… If you manage to solve it, please let us know!

Have you discovered any useful details?

Did it appear within the last 9 days?

On February 6th I installed ERPNext using the Easy Install Script, everything worked perfectly. Since then I tried to install it on different VMs (all running the exact same OS) and always got the above mentioned error. So to be specific, I got the issue multiple times in the last six days, but not before then.

Maybe there was a weekend in there :crazy_face:

Any way there’s this : ErpNext Releases

Haha :laughing:

The successful installation from February 6th is also v12.4.3, just looked it up.

That almost certainly means we are seeing a bug in a dependency.

Could you list the pip version numbers from the good installation and from a bad one?

I don’t think it’s a dependency problem, because if I install a new database for the working installation, the setup fails also.

bench --site site1.local --force reinstall

Anyway, if it helps in any way:

Package                  Version    Location                                
------------------------ ---------- ----------------------------------------
argh                     0.26.2
Babel 2.6.0
backcall 0.1.0
beautifulsoup4 4.8.2
bleach 2.1.4
bleach-whitelist 0.0.10
boto3 1.11.10
botocore 1.14.10
braintree 3.58.0
cachetools 4.0.0
certifi 2019.11.28
cffi 1.13.2
chardet 3.0.4
Click 7.0
coverage 5.0.3
croniter 0.3.31
cryptography 2.8
cssselect 1.1.0
cssutils 1.0.2
decorator 4.4.1
Deprecated 1.2.7
docutils 0.15.2
dropbox 9.1.0
email-reply-parser 0.5.9
erpnext 12.4.3 /home/frappe/frappe-bench/apps/erpnext
et-xmlfile 1.0.1
Faker 2.0.4
frappe 12.2.1 /home/frappe/frappe-bench/apps/frappe
frontmatter 3.0.5
future 0.18.2
gitdb2 2.0.6
GitPython 2.1.11
gocardless-pro 1.12.1
google-api-python-client 1.7.11
google-auth 1.11.0
google-auth-httplib2 0.0.3
google-auth-oauthlib 0.4.1
googlemaps 3.1.1
gunicorn 20.0.4
html2text 2016.9.19
html5lib 1.0.1
httplib2 0.17.0
idna 2.8
ipython 7.12.0
ipython-genutils 0.2.0
jdcal 1.4.1
jedi 0.16.0
Jinja2 2.11.1
jmespath 0.9.4
lxml 4.5.0
markdown2 2.3.6
MarkupSafe 1.1.1
maxminddb 1.5.2
maxminddb-geolite2 2018.703
ndg-httpsclient 0.5.1
num2words 0.5.5
numpy 1.18.1
oauthlib 3.1.0
openpyxl 3.0.3
ordereddict 1.1
pandas 1.0.0
parso 0.6.1
passlib 1.7.2
pathtools 0.1.2
pdfkit 0.5.0 /home/frappe/frappe-bench/env/src/pdfkit
pexpect 4.8.0
pickleshare 0.7.5
Pillow 7.0.0
pip 19.3.1
plaid-python 3.5.0
premailer 3.6.1
prompt-toolkit 3.0.3
psycopg2-binary 2.8.4
ptyprocess 0.6.0
pyasn1 0.4.8
pyasn1-modules 0.2.8
pycparser 2.19
PyGithub 1.45
Pygments 2.2.0
PyJWT 1.7.1
PyMySQL 0.9.3
pyOpenSSL 19.1.0
pyotp 2.3.0
PyPDF2 1.26.0
pypng 0.0.20
PyQRCode 1.2.1
python-dateutil 2.8.1
python-stdnum 1.13
pytz 2019.3
PyYAML 3.13
rauth 0.7.3
redis 2.10.6
requests 2.22.0
requests-oauthlib 1.3.0
RestrictedPython 5.0
rq 0.12.0
rsa 4.0
s3transfer 0.3.2
schedule 0.6.0
selenium 3.141.0
semantic-version 2.8.4
setuptools 45.1.0
six 1.14.0
smmap2 2.0.5
soupsieve 1.9.5
sqlparse 0.2.4
stripe 2.42.0
text-unidecode 1.3
traitlets 4.3.3
Unidecode 1.1.1
unittest-xml-reporting 2.5.2
uritemplate 3.0.1
urllib3 1.25.8
watchdog 0.8.0
wcwidth 0.1.8
webencodings 0.5.1
Werkzeug 0.16.1
wheel 0.34.2
WooCommerce 2.1.1
wrapt 1.11.2
xlrd 1.2.0
zxcvbn-python 4.4.24

I don’t have the list of the non working installation, because I already deleted the VM. However I might give it another chance later, if it fails again I’ll post the list!

Could you elaborate please?
I don’t know what you mean by that.

After I run:

bench --site site1.local --force reinstall

no dependencies change, only a new database is created. So the installation per se is the same.

So that wrecks your working installation?

What do you do to revert to a working state?

Exactly. I have a snapshot of the VM in the working state.

So reinstall is supplying a new defective database?

Really wishing a committer would jump in round about now … :wave:

At least it seems like it.

So I compared your pip installed dependencies with mine and there are many differences.

Are you certain that reinstall leaves dependencies untouched?

1,3c1,3
< boto3 1.11.10
< botocore 1.14.10
< braintree 3.58.0
---
> boto3 1.11.15
> botocore 1.14.15
> braintree 3.59.0
6c6
< cffi 1.13.2
---
> cffi 1.14.0
27c27
< gocardless-pro 1.12.1
---
> gocardless-pro 1.14.0
55c55
< pandas 1.0.0
---
> pandas 1.0.1
63,64c63,64
< pip 19.3.1
< plaid-python 3.5.0
---
> pip 20.0.2
> plaid-python 3.6.0
72c72
< PyGithub 1.45
---
> PyGithub 1.46
92c92
< s3transfer 0.3.2
---
> s3transfer 0.3.3
96c96
< setuptools 45.1.0
---
> setuptools 45.2.0
105c105
< unittest-xml-reporting 2.5.2
---
> unittest-xml-reporting 3.0.1
111c111
< Werkzeug 0.16.1
---
> Werkzeug 0.16.0

Update 2020/02/12 15:00 EST

So I tried reverting all pip dependencies to the ones @bene has in his working installation.
It made no difference, except that yet another different setting is involved

make_property_setter(doctype, "naming_series", "hidden", 1, "Check")