search

10gen / mongo-orchestration

Apache License 2.0
7 stars 11 forks source link

Capture server startup errors in log files stdout/stderr to the server's log file #279

Closed ShaneHarvey closed 4 years ago

ShaneHarvey commented 4 years ago

The nice thing about this change is that we now capture server start-up errors. For example, errors like [main] Failed global initialization: BadValue: Unknown --setParameter 'failpoint.disableStapling' will now be shown in the logs:

2020-02-26 10:30:57,888 [DEBUG] mongo_orchestration.server:184 - Starting mongo-orchestration in the foreground
2020-02-26 10:30:57,889 [DEBUG] mongo_orchestration.server:131 - Starting HTTP server on host: localhost; port: 8889
2020-02-26 10:31:06,893 [DEBUG] mongo_orchestration.apps:64 - rs_create((), {})
2020-02-26 10:31:06,893 [DEBUG] mongo_orchestration.apps.replica_sets:77 - rs_create()
2020-02-26 10:31:06,894 [DEBUG] mongo_orchestration.servers:168 - Server.__init__(mongod, {u'bind_ip': u'127.0.0.1,::1', 'replSet': '35610070-c498-4290-be0b-805ea12a64f1', u'ipv6': True, u'setParameter': {u'enableTestCommands': 1, u'failpoint.disableStapling': u'{"mode":"alwaysOn"}'}, u'logappend': True, u'port': 27017}, {}, None, None, None)
2020-02-26 10:31:06,894 [DEBUG] mongo_orchestration.servers:68 - Creating log file for mongod: /var/folders/t0/h63967912lv9gj5m78g80wk80000gp/T/mongod-2VkU2E/mongod.log
2020-02-26 10:31:06,894 [DEBUG] mongo_orchestration.servers:229 - ('mongod', '--version')
2020-02-26 10:31:06,917 [DEBUG] mongo_orchestration.process:220 - mprocess(name='mongod', config_path='/var/folders/t0/h63967912lv9gj5m78g80wk80000gp/T/mongo-nbhL8F', port=27017, timeout=300)
2020-02-26 10:31:06,918 [DEBUG] mongo_orchestration.process:232 - execute process: mongod --config /var/folders/t0/h63967912lv9gj5m78g80wk80000gp/T/mongo-nbhL8F --port 27017
2020-02-26 10:31:06,923 [DEBUG] mongo_orchestration.process:166 - wait for 27017
2020-02-26 10:31:06,948 [DEBUG] mongo_orchestration.process:171 - process is not alive
2020-02-26 10:31:06,948 [ERROR] mongo_orchestration.servers:370 - Could not start Server. Please find server log below.
=====================================================
2020-02-26 10:31:06,948 [ERROR] mongo_orchestration.servers:373 - 2020-02-26T10:31:06.946-0800 F  CONTROL  [main] Failed global initialization: BadValue: Unknown --setParameter 'failpoint.disableStapling'

2020-02-26 10:31:06,949 [ERROR] mongo_orchestration.apps:68 - <function rs_create at 0x1026e6ed8>
Traceback (most recent call last):
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/apps/__init__.py", line 66, in wrap
    return f(*arg, **kwd)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/apps/replica_sets.py", line 80, in rs_create
    result = _rs_create(data)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/apps/replica_sets.py", line 37, in _rs_create
    rs_id = ReplicaSets().create(params)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/replica_sets.py", line 643, in create
    repl = ReplicaSet(rs_params)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/replica_sets.py", line 74, in __init__
    for index, member in enumerate(members)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/replica_sets.py", line 317, in member_create
    server_id=server_id
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/servers.py", line 520, in create
    server.start(timeout)
  File "/Users/shane/git/mongo-orchestration/mongo_orchestration/servers.py", line 382, in start
    LOG_FILE + ' for more details.')
  File "<string>", line 2, in reraise
TimeoutError: Could not start Server. Please check server log located in /var/folders/t0/h63967912lv9gj5m78g80wk80000gp/T/mongod-2VkU2E/mongod.log or the mongo-orchestration log in /Users/shane/mongo-orchestration/server.log for more details.
2020-02-26 10:31:06,949 [DEBUG] mongo_orchestration.apps:55 - send_result(500)

Two changes:

CC: @vincentkam

ShaneHarvey commented 4 years ago

I had to revert this change because it's causing these failures on Windows:

 [2020/02/26 12:45:05.619] + curl --silent --show-error --data @C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/configs/servers/auth.json http://localhost:8889/v1/servers --max-time 600 --fail -o tmp.json
 [2020/02/26 12:45:05.822] curl: (22) The requested URL returned error: 500 Internal Server Error
 [2020/02/26 12:45:05.822] Failed to start cluster, see C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/out.log:
 [2020/02/26 12:45:05.822] + echo Failed to start cluster, see C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/out.log:
 [2020/02/26 12:45:05.822] + cat C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/out.log
 [2020/02/26 12:45:05.822] Preparing to start mongo-orchestration daemon
 [2020/02/26 12:45:05.822] Daemon process started with pid: 3320
 [2020/02/26 12:45:05.822] + echo Failed to start cluster, see C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/server.log:
 [2020/02/26 12:45:05.822] Failed to start cluster, see C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/server.log:
 [2020/02/26 12:45:05.822] + cat C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/server.log
 [2020/02/26 12:45:05.856] From shell Wed, Feb 26, 2020 8:44:44 PM
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:54,789 [INFO] mongo_orchestration.daemon:132 - Starting daemon
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:54,789 [INFO] mongo_orchestration.daemon:57 - daemonize_win32: ['C:\\data\\mci\\4a8e5e162474e3a7efd75360b86dfa07\\drivers-tools\\.evergreen\\orchestration\\venv\\Scripts\\mongo-orchestration', '-e', 'default', '-f', 'C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration/orchestration.config', '--socket-timeout-ms=60000', '--bind=127.0.0.1', '--enable-majority-read-concern', '-s', 'wsgiref', 'start']
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:54,930 [DEBUG] mongo_orchestration.server:182 - Starting mongo-orchestration in the foreground
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:54,930 [DEBUG] mongo_orchestration.server:131 - Starting HTTP server on host: 127.0.0.1; port: 8889
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:59,506 [DEBUG] mongo_orchestration.apps:64 - base_uri((), {})
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:59,506 [DEBUG] mongo_orchestration.apps.servers:61 - base_uri()
 [2020/02/26 12:45:05.856] 2020-02-26 20:44:59,506 [DEBUG] mongo_orchestration.apps:55 - send_result(200)
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,756 [DEBUG] mongo_orchestration.apps:64 - host_create((), {})
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,756 [DEBUG] mongo_orchestration.servers:166 - Server.__init__(C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/mongodb/bin\mongod, {u'journal': True, u'logappend': True, u'bind_ip': u'127.0.0.1,::1', u'port': 27017, u'ipv6': True}, {}, secret, bob, pwd123)
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,756 [DEBUG] mongo_orchestration.servers:66 - Creating log file for C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/mongodb/bin\mongod: c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\db\mongod-knmnrp\mongod.log
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,756 [DEBUG] mongo_orchestration.servers:227 - (u'C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/mongodb/bin\\mongod', '--version')
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,772 [DEBUG] mongo_orchestration.process:218 - mprocess(name=u'C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/mongodb/bin\\mongod', config_path='c:\\data\\mci\\4a8e5e162474e3a7efd75360b86dfa07\\drivers-tools\\.evergreen\\orchestration\\db\\mongo-mvycmn', port=27017, timeout=300)
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,772 [DEBUG] mongo_orchestration.process:230 - execute process: C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/mongodb/bin\mongod --config c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\db\mongo-mvycmn --port 27017
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:04,772 [DEBUG] mongo_orchestration.process:166 - wait for 27017
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:05,822 [DEBUG] mongo_orchestration.process:171 - process is not alive
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:05,822 [ERROR] mongo_orchestration.servers:368 - Could not start Server. Please find server log below.
 [2020/02/26 12:45:05.856] =====================================================
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:05,822 [ERROR] mongo_orchestration.servers:371 - 2020-02-26T20:45:04.803+0000 SEVERE: Failed global initialization: FileNotOpen Failed to open "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\db\mongod-knmnrp\mongod.log"
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:05,822 [ERROR] mongo_orchestration.apps:68 - <function host_create at 0x0000000002049F98>
 [2020/02/26 12:45:05.856] Traceback (most recent call last):
 [2020/02/26 12:45:05.856]   File "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\__init__.py", line 66, in wrap
 [2020/02/26 12:45:05.856]     return f(*arg, **kwd)
 [2020/02/26 12:45:05.856]   File "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\servers.py", line 83, in host_create
 [2020/02/26 12:45:05.856]     result = _host_create(data)
 [2020/02/26 12:45:05.856]   File "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\apps\servers.py", line 52, in _host_create
 [2020/02/26 12:45:05.856]     params.get('version', ''))
 [2020/02/26 12:45:05.856]   File "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 518, in create
 [2020/02/26 12:45:05.856]     server.start(timeout)
 [2020/02/26 12:45:05.856]   File "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\venv\lib\site-packages\mongo_orchestration\servers.py", line 380, in start
 [2020/02/26 12:45:05.856]     LOG_FILE + ' for more details.')
 [2020/02/26 12:45:05.856]   File "<string>", line 2, in reraise
 [2020/02/26 12:45:05.856] TimeoutError: Could not start Server. Please check server log located in c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\db\mongod-knmnrp\mongod.log or the mongo-orchestration log in C:/data/mci/4a8e5e162474e3a7efd75360b86dfa07/drivers-tools/.evergreen/orchestration\server.log for more details.
 [2020/02/26 12:45:05.856] 2020-02-26 20:45:05,822 [DEBUG] mongo_orchestration.apps:55 - send_result(500)
 [2020/02/26 12:45:05.872] + exit 1

The important line is 2020-02-26T20:45:04.803+0000 SEVERE: Failed global initialization: FileNotOpen Failed to open "c:\data\mci\4a8e5e162474e3a7efd75360b86dfa07\drivers-tools\.evergreen\orchestration\db\mongod-knmnrp\mongod.log".