search

Azure / WALinuxAgent

Microsoft Azure Linux Guest Agent
http://azure.microsoft.com/
Apache License 2.0
541 stars 372 forks source link

Service walinuxagent is dead and hang while manually starting on Debian 8 #767

Closed beelesnik closed 7 years ago

beelesnik commented 7 years ago

Good day.

I have created VM based on standard image of Debian 8. Then I made some customization for our organization needs (LDAP authentication, installing packages and so on). After that I saw that service walinuxagent is dead. And it hangs while manually starting.

I noticed that I have 2.2.2 version of walinuxagent amd tried to install newest version - 2.2.13. But problem was not solved.

It looks like this:

waagent -version WALinuxAgent-2.2.13 running on debian 8.8 Python: 2.7.9 Goal state agent: 2.2.13

systemctl status walinuxagent ● walinuxagent.service - Microsft Azure Linux Agent Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled) Active: inactive (dead)

debian-lsn sergey.lozenkov # journalctl -u walinuxagent -- Logs begin at Fri 2017-06-16 00:19:27 UTC, end at Fri 2017-06-16 18:04:29 UTC. --

debian-lsn sergey.lozenkov # systemctl stop walinuxagent debian-lsn sergey.lozenkov # systemctl start walinuxagent

<-- It hangs there forever -->

When I create VM based on standard Debian 8 image without any customization all works good.

root@cleardebian8:/# waagent -version WALinuxAgent-2.2.2 running on debian 8.7 Python: 3.4.2 Goal state agent: b'2.2.13' root@cleardebian8:/# systemctl status walinuxagent ● walinuxagent.service - Microsft Azure Linux Agent Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled) Active: active (running) since Thu 2017-06-15 23:05:40 UTC; 19h ago Main PID: 481 (waagent) CGroup: /system.slice/walinuxagent.service ├─481 /usr/bin/python3 /usr/sbin/waagent -daemon └─498 python3 -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers

I have not seen any information about walinuxagent in log files, like messages and waagent.log

And for me necessary correct behaviour of walinuxagent.

Could anyone help to diagnose and solve the problem? I would be appreciate

brendandixon commented 7 years ago

@beelesnik If the agent is encountering errors or problems, its log -- /var/log/waagent.log -- should provide more details. Reading the log requires some care since not messages that appear to be bad are truly indicative of bad things. However, take a look there and see what "jumps out" at you.

beelesnik commented 7 years ago

Ok. I've done folllowing.

  1. Created new VM from standard Debian 8 image
  2. Enabled verbose logging and disabled auto-update for waagent
  3. Updated manually waagent to 2.2.13 and again in configuration file enabled verbose logging and disable auto-update
  4. walinuxagent works good at that moment
  5. I have tried to make special customization for this clean VM and after some operations (some customization steps with VM reboots) I have got dead walinuxagent. I put a link to pastebin site in this comment and plaint text in the next comment, You will see that in waagent log walinuxagent kill itself at the end. But why? And what should I do to make him alive? https://pastebin.com/Ft1tzhtA
beelesnik commented 7 years ago

Tue Jun 20 06:53:54 UTC 2017 --- walinuxagent is working

Tue Jun 20 06:53:54 UTC 2017

WALinuxAgent-2.2.13 running on debian 8.8 Python: 2.7.9 Goal state agent: 2.2.13

Tue Jun 20 07:05:28 UTC 2017 --- walinuxagent is working

Tue Jun 20 07:05:28 UTC 2017

WALinuxAgent-2.2.13 running on debian 8.8 Python: 2.7.9 Goal state agent: 2.2.13

 * walinuxagent.service - Microsft Azure Linux Agent
       Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled)
       Active: active (running) since Tue 2017-06-20 06:52:14 UTC; 13min ago
     Main PID: 477 (python)
       CGroup: /system.slice/walinuxagent.service
               |-477 python /usr/sbin/waagent -daemon
               `-568 python -u /usr/sbin/waagent -run-exthandlers

    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.009729 INFO Routes:None
    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.077847 INFO WALinuxAgent-2.2.13 running as process 568
    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.078053 INFO Set block dev timeout: sda with timeout: 300
    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.097578 INFO Wire server endpoint:168.63.129.16
    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.115439 INFO Set block dev timeout: sdb with timeout: 300
    Jun 20 06:52:20 debian-lsn waagent[477]: 2017/06/20 06:52:20.832956 INFO Event: name=WALinuxAgent, op=ProcessGoalState, message=
    Jun 20 06:53:15 debian-lsn waagent[477]: 2017/06/20 06:53:15.387276 INFO EnvMonitor: Detected dhcp client restart. Restoring routing table.
    Jun 20 06:53:15 debian-lsn waagent[477]: 2017/06/20 06:53:15.414326 INFO Configure routes
    Jun 20 06:53:15 debian-lsn waagent[477]: 2017/06/20 06:53:15.420186 INFO Gateway:None
    Jun 20 06:53:15 debian-lsn waagent[477]: 2017/06/20 06:53:15.425321 INFO Routes:None

        2017/06/20 07:06:06.096940 VERBOSE Agent WALinuxAgent-2.2.13 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:06.110127 VERBOSE Ensuring Agent WALinuxAgent-2.2.13 is downloaded
    2017/06/20 07:06:06.119273 VERBOSE Agent WALinuxAgent-2.2.13 was previously downloaded - skipping download
    2017/06/20 07:06:06.130720 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json
    2017/06/20 07:06:06.145841 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}
    2017/06/20 07:06:06.190407 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk
    2017/06/20 07:06:06.199360 VERBOSE Agent WALinuxAgent-2.2.12 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:06.211743 VERBOSE Ensuring Agent WALinuxAgent-2.2.12 is downloaded
    2017/06/20 07:06:06.220767 VERBOSE Agent WALinuxAgent-2.2.12 was previously downloaded - skipping download
    2017/06/20 07:06:06.231682 VERBOSE Agent WALinuxAgent-2.2.12 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.12/HandlerManifest.json
    2017/06/20 07:06:06.245522 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.12 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}
    2017/06/20 07:06:09.286341 VERBOSE Get extension handler config
    2017/06/20 07:06:09.293867 VERBOSE HTTP connection [GET] [/machine/?comp=goalstate] [None] [{'x-ms-version': '2012-11-30', 'x-ms-agent-name': 'WALinuxAgent'}]
    2017/06/20 07:06:09.311274 VERBOSE HTTP response status: [200]
    2017/06/20 07:06:09.318551 VERBOSE Load GoalState.xml
    2017/06/20 07:06:09.325536 VERBOSE Handle extensions updates for incarnation 1
    2017/06/20 07:06:09.334291 VERBOSE No extension handler config found
    2017/06/20 07:06:09.341877 VERBOSE Report vm agent status
    2017/06/20 07:06:09.348326 VERBOSE Prepare status blob
    2017/06/20 07:06:09.354749 VERBOSE Put page blob
    2017/06/20 07:06:09.360898 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw] [] [{'Content-Length': '0', 'x-ms-blob-content-length': u'512', 'x-ms-version': '2014-02-14', 'x-ms-blob-type': 'PageBlob', 'x-ms-date': '2017-06-20T07:06:09Z'}]
    2017/06/20 07:06:09.414955 VERBOSE HTTP response status: [201]
    2017/06/20 07:06:09.423353 VERBOSE Upload page blob
    2017/06/20 07:06:09.429889 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw&comp=page] [{"aggregateStatus": {"guestAgentStatus": {"status": "Ready", "formattedMessage": {"lang": "en-US", "message": "Guest Agent is running"}, "hostname": "debian-lsn", "osname": "debian", "version": "2.2.13", "osversion": "8.8"}, "handlerAggregateStatus": []}, "version": "1.1", "timestampUTC": "2017-06-20T07:06:09Z"}] [{'x-ms-version': '2014-02-14', 'Content-Length': u'512', 'x-ms-range': 'bytes=0-511', 'x-ms-page-write': 'update', 'x-ms-date': '2017-06-20T07:06:09Z'}]
    2017/06/20 07:06:09.584427 VERBOSE HTTP response status: [201]
    2017/06/20 07:06:09.592173 VERBOSE Completed vm agent status report
    2017/06/20 07:06:09.600688 VERBOSE Instantiating Agent WALinuxAgent-2.2.10 from disk
    2017/06/20 07:06:09.610002 VERBOSE Agent WALinuxAgent-2.2.10 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:09.622574 VERBOSE Ensuring Agent WALinuxAgent-2.2.10 is downloaded
    2017/06/20 07:06:09.631505 VERBOSE Agent WALinuxAgent-2.2.10 was previously downloaded - skipping download
    2017/06/20 07:06:09.642862 VERBOSE Agent WALinuxAgent-2.2.10 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.10/HandlerManifest.json
    2017/06/20 07:06:09.657048 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.10 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.10-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}
    2017/06/20 07:06:09.695569 VERBOSE Instantiating Agent WALinuxAgent-2.2.8 from disk
    2017/06/20 07:06:09.704465 VERBOSE Agent WALinuxAgent-2.2.8 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:09.716690 VERBOSE Ensuring Agent WALinuxAgent-2.2.8 is downloaded
    2017/06/20 07:06:09.725433 VERBOSE Agent WALinuxAgent-2.2.8 was previously downloaded - skipping download
    2017/06/20 07:06:09.736292 VERBOSE Agent WALinuxAgent-2.2.8 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.8/HandlerManifest.json
    2017/06/20 07:06:09.750492 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.8 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.8-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}
    2017/06/20 07:06:09.788986 VERBOSE Instantiating Agent WALinuxAgent-2.2.13 from disk
    2017/06/20 07:06:09.797933 VERBOSE Agent WALinuxAgent-2.2.13 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:09.810505 VERBOSE Ensuring Agent WALinuxAgent-2.2.13 is downloaded
    2017/06/20 07:06:09.819308 VERBOSE Agent WALinuxAgent-2.2.13 was previously downloaded - skipping download
    2017/06/20 07:06:09.830515 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json
    2017/06/20 07:06:09.844846 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}
    2017/06/20 07:06:09.883538 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk
    2017/06/20 07:06:09.892809 VERBOSE Agent WALinuxAgent-2.2.12 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False
    2017/06/20 07:06:09.905305 VERBOSE Ensuring Agent WALinuxAgent-2.2.12 is downloaded
    2017/06/20 07:06:09.914409 VERBOSE Agent WALinuxAgent-2.2.12 was previously downloaded - skipping download
    2017/06/20 07:06:09.925685 VERBOSE Agent WALinuxAgent-2.2.12 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.12/HandlerManifest.json
    2017/06/20 07:06:09.939817 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.12 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'}

Tue Jun 20 07:10:36 UTC 2017 --- walinuxagent is not working

    Tue Jun 20 07:10:36 UTC 2017

    WALinuxAgent-2.2.13 running on debian 8.8
    Python: 2.7.9
    Goal state agent: 2.2.13

    * walinuxagent.service - Microsft Azure Linux Agent
       Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled)
       Active: inactive (dead)

2017/06/20 07:06:42.301704 VERBOSE Agent WALinuxAgent-2.2.10 was previously downloaded - skipping download 2017/06/20 07:06:42.313647 VERBOSE Agent WALinuxAgent-2.2.10 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.10/HandlerManifest.json 2017/06/20 07:06:42.331293 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.10 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.10-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:42.370911 VERBOSE Instantiating Agent WALinuxAgent-2.2.8 from disk 2017/06/20 07:06:42.380212 VERBOSE Agent WALinuxAgent-2.2.8 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:42.393501 VERBOSE Ensuring Agent WALinuxAgent-2.2.8 is downloaded 2017/06/20 07:06:42.402521 VERBOSE Agent WALinuxAgent-2.2.8 was previously downloaded - skipping download 2017/06/20 07:06:42.414090 VERBOSE Agent WALinuxAgent-2.2.8 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.8/HandlerManifest.json 2017/06/20 07:06:42.428265 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.8 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.8-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:42.485636 VERBOSE Instantiating Agent WALinuxAgent-2.2.13 from disk 2017/06/20 07:06:42.495242 VERBOSE Agent WALinuxAgent-2.2.13 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:42.508665 VERBOSE Ensuring Agent WALinuxAgent-2.2.13 is downloaded 2017/06/20 07:06:42.517848 VERBOSE Agent WALinuxAgent-2.2.13 was previously downloaded - skipping download 2017/06/20 07:06:42.529285 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json 2017/06/20 07:06:42.543071 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:42.587500 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk 2017/06/20 07:06:42.597012 VERBOSE Agent WALinuxAgent-2.2.12 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:42.610213 VERBOSE Ensuring Agent WALinuxAgent-2.2.12 is downloaded 2017/06/20 07:06:42.620284 VERBOSE Agent WALinuxAgent-2.2.12 was previously downloaded - skipping download 2017/06/20 07:06:42.638584 VERBOSE Agent WALinuxAgent-2.2.12 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.12/HandlerManifest.json 2017/06/20 07:06:42.653512 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.12 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:45.700237 VERBOSE Get extension handler config 2017/06/20 07:06:45.707748 VERBOSE HTTP connection [GET] [/machine/?comp=goalstate] [None] [{'x-ms-version': '2012-11-30', 'x-ms-agent-name': 'WALinuxAgent'}] 2017/06/20 07:06:45.724987 VERBOSE HTTP response status: [200] 2017/06/20 07:06:45.732338 VERBOSE Load GoalState.xml 2017/06/20 07:06:45.739409 VERBOSE Handle extensions updates for incarnation 1 2017/06/20 07:06:45.748075 VERBOSE No extension handler config found 2017/06/20 07:06:45.755471 VERBOSE Report vm agent status 2017/06/20 07:06:45.761977 VERBOSE Prepare status blob 2017/06/20 07:06:45.768625 VERBOSE Put page blob 2017/06/20 07:06:45.774631 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw] [] [{'Content-Length': '0', 'x-ms-blob-content-length': u'512', 'x-ms-version': '2014-02-14', 'x-ms-blob-type': 'PageBlob', 'x-ms-date': '2017-06-20T07:06:45Z'}] 2017/06/20 07:06:45.828832 VERBOSE HTTP response status: [201] 2017/06/20 07:06:45.836104 VERBOSE Upload page blob 2017/06/20 07:06:45.842775 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw&comp=page] [{"aggregateStatus": {"guestAgentStatus": {"status": "Ready", "formattedMessage": {"lang": "en-US", "message": "Guest Agent is running"}, "hostname": "debian-lsn", "osname": "debian", "version": "2.2.13", "osversion": "8.8"}, "handlerAggregateStatus": []}, "version": "1.1", "timestampUTC": "2017-06-20T07:06:45Z"}] [{'x-ms-version': '2014-02-14', 'Content-Length': u'512', 'x-ms-range': 'bytes=0-511', 'x-ms-page-write': 'update', 'x-ms-date': '2017-06-20T07:06:45Z'}] 2017/06/20 07:06:45.991277 VERBOSE HTTP response status: [201] 2017/06/20 07:06:45.998813 VERBOSE Completed vm agent status report 2017/06/20 07:06:46.006900 VERBOSE Instantiating Agent WALinuxAgent-2.2.10 from disk 2017/06/20 07:06:46.016065 VERBOSE Agent WALinuxAgent-2.2.10 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:46.028602 VERBOSE Ensuring Agent WALinuxAgent-2.2.10 is downloaded 2017/06/20 07:06:46.037445 VERBOSE Agent WALinuxAgent-2.2.10 was previously downloaded - skipping download 2017/06/20 07:06:46.048308 VERBOSE Agent WALinuxAgent-2.2.10 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.10/HandlerManifest.json 2017/06/20 07:06:46.062203 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.10 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.10-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:46.099797 VERBOSE Instantiating Agent WALinuxAgent-2.2.8 from disk 2017/06/20 07:06:46.108963 VERBOSE Agent WALinuxAgent-2.2.8 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:46.121183 VERBOSE Ensuring Agent WALinuxAgent-2.2.8 is downloaded 2017/06/20 07:06:46.130243 VERBOSE Agent WALinuxAgent-2.2.8 was previously downloaded - skipping download 2017/06/20 07:06:46.141059 VERBOSE Agent WALinuxAgent-2.2.8 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.8/HandlerManifest.json 2017/06/20 07:06:46.154986 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.8 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.8-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:46.193376 VERBOSE Instantiating Agent WALinuxAgent-2.2.13 from disk 2017/06/20 07:06:46.202521 VERBOSE Agent WALinuxAgent-2.2.13 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:46.215061 VERBOSE Ensuring Agent WALinuxAgent-2.2.13 is downloaded 2017/06/20 07:06:46.224154 VERBOSE Agent WALinuxAgent-2.2.13 was previously downloaded - skipping download 2017/06/20 07:06:46.235280 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json 2017/06/20 07:06:46.249410 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:46.287598 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk 2017/06/20 07:06:46.296677 VERBOSE Agent WALinuxAgent-2.2.12 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:46.309516 VERBOSE Ensuring Agent WALinuxAgent-2.2.12 is downloaded 2017/06/20 07:06:46.318572 VERBOSE Agent WALinuxAgent-2.2.12 was previously downloaded - skipping download 2017/06/20 07:06:46.329693 VERBOSE Agent WALinuxAgent-2.2.12 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.12/HandlerManifest.json 2017/06/20 07:06:46.343847 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.12 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:49.385514 VERBOSE Get extension handler config 2017/06/20 07:06:49.395097 VERBOSE HTTP connection [GET] [/machine/?comp=goalstate] [None] [{'x-ms-version': '2012-11-30', 'x-ms-agent-name': 'WALinuxAgent'}] 2017/06/20 07:06:49.421107 VERBOSE HTTP response status: [200] 2017/06/20 07:06:49.429469 VERBOSE Load GoalState.xml 2017/06/20 07:06:49.437407 VERBOSE Handle extensions updates for incarnation 1 2017/06/20 07:06:49.447231 VERBOSE No extension handler config found 2017/06/20 07:06:49.455874 VERBOSE Report vm agent status 2017/06/20 07:06:49.462101 VERBOSE Prepare status blob 2017/06/20 07:06:49.468115 VERBOSE Put page blob 2017/06/20 07:06:49.474706 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw] [] [{'Content-Length': '0', 'x-ms-blob-content-length': u'512', 'x-ms-version': '2014-02-14', 'x-ms-blob-type': 'PageBlob', 'x-ms-date': '2017-06-20T07:06:49Z'}] 2017/06/20 07:06:49.551741 VERBOSE HTTP response status: [201] 2017/06/20 07:06:49.563631 VERBOSE Upload page blob 2017/06/20 07:06:49.571061 VERBOSE HTTP connection [PUT] [/$system/debian-lsn.ee47a80e-1d63-48b7-a8b9-246e968c58ed.status?sv=2016-05-31&sr=b&sk=system-1&sig=HhzFAs6JIuFF9fTh9JHwIvaToMlupdsNhtdPDVxWPvs%3d&se=9999-01-01T00%3a00%3a00Z&sp=rw&comp=page] [{"aggregateStatus": {"guestAgentStatus": {"status": "Ready", "formattedMessage": {"lang": "en-US", "message": "Guest Agent is running"}, "hostname": "debian-lsn", "osname": "debian", "version": "2.2.13", "osversion": "8.8"}, "handlerAggregateStatus": []}, "version": "1.1", "timestampUTC": "2017-06-20T07:06:49Z"}] [{'x-ms-version': '2014-02-14', 'Content-Length': u'512', 'x-ms-range': 'bytes=0-511', 'x-ms-page-write': 'update', 'x-ms-date': '2017-06-20T07:06:49Z'}] 2017/06/20 07:06:49.728570 VERBOSE HTTP response status: [201] 2017/06/20 07:06:49.736098 VERBOSE Completed vm agent status report 2017/06/20 07:06:49.744705 VERBOSE Instantiating Agent WALinuxAgent-2.2.10 from disk 2017/06/20 07:06:49.754166 VERBOSE Agent WALinuxAgent-2.2.10 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:49.766846 VERBOSE Ensuring Agent WALinuxAgent-2.2.10 is downloaded 2017/06/20 07:06:49.775937 VERBOSE Agent WALinuxAgent-2.2.10 was previously downloaded - skipping download 2017/06/20 07:06:49.787128 VERBOSE Agent WALinuxAgent-2.2.10 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.10/HandlerManifest.json 2017/06/20 07:06:49.801217 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.10 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.10-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:49.839849 VERBOSE Instantiating Agent WALinuxAgent-2.2.8 from disk 2017/06/20 07:06:49.849040 VERBOSE Agent WALinuxAgent-2.2.8 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:49.862151 VERBOSE Ensuring Agent WALinuxAgent-2.2.8 is downloaded 2017/06/20 07:06:49.871331 VERBOSE Agent WALinuxAgent-2.2.8 was previously downloaded - skipping download 2017/06/20 07:06:49.882741 VERBOSE Agent WALinuxAgent-2.2.8 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.8/HandlerManifest.json 2017/06/20 07:06:49.896984 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.8 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.8-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:49.936712 VERBOSE Instantiating Agent WALinuxAgent-2.2.13 from disk 2017/06/20 07:06:49.946133 VERBOSE Agent WALinuxAgent-2.2.13 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:49.959208 VERBOSE Ensuring Agent WALinuxAgent-2.2.13 is downloaded 2017/06/20 07:06:49.968318 VERBOSE Agent WALinuxAgent-2.2.13 was previously downloaded - skipping download 2017/06/20 07:06:49.979717 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json 2017/06/20 07:06:49.994412 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:50.034429 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk 2017/06/20 07:06:50.043631 VERBOSE Agent WALinuxAgent-2.2.12 error state: Last Failure: 0.0, Total Failures: 0, Fatal: False 2017/06/20 07:06:50.059841 VERBOSE Ensuring Agent WALinuxAgent-2.2.12 is downloaded 2017/06/20 07:06:50.069097 VERBOSE Agent WALinuxAgent-2.2.12 was previously downloaded - skipping download 2017/06/20 07:06:50.080501 VERBOSE Agent WALinuxAgent-2.2.12 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.12/HandlerManifest.json 2017/06/20 07:06:50.095007 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.12 HandlerManifest.json: {u'version': 1.0, u'handlerManifest': {u'uninstallCommand': u'', u'enableCommand': u'python -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers', u'installCommand': u'', u'rebootAfterInstall': False, u'updateCommand': u'', u'disableCommand': u'', u'reportHeartbeat': False}, u'name': u'WALinuxAgent'} 2017/06/20 07:06:50.862248 INFO Agent WALinuxAgent-2.2.13 forwarding signal 15 to WALinuxAgent-2.2.13

Configuration file 

    #
    # Microsoft Azure Linux Agent Configuration
    #

    # Enable instance creation
    Provisioning.Enabled=y

    # Rely on cloud-init to provision
    Provisioning.UseCloudInit=n

    # Password authentication for root account will be unavailable.
    Provisioning.DeleteRootPassword=y

    # Generate fresh host key pair.
    Provisioning.RegenerateSshHostKeyPair=y

    # Supported values are "rsa", "dsa" and "ecdsa".
    Provisioning.SshHostKeyPairType=rsa

    # Monitor host name changes and publish changes via DHCP requests.
    Provisioning.MonitorHostName=y

    # Decode CustomData from Base64.
    Provisioning.DecodeCustomData=n

    # Execute CustomData after provisioning.
    Provisioning.ExecuteCustomData=n

    # Algorithm used by crypt when generating password hash.
    #Provisioning.PasswordCryptId=6

    # Length of random salt used when generating password hash.
    #Provisioning.PasswordCryptSaltLength=10

    # Allow reset password of sys user
    Provisioning.AllowResetSysUser=n

    # Format if unformatted. If 'n', resource disk will not be mounted.
    ResourceDisk.Format=y

    # File system on the resource disk
    # Typically ext3 or ext4. FreeBSD images should use 'ufs2' here.
    ResourceDisk.Filesystem=ext4

    # Mount point for the resource disk
    ResourceDisk.MountPoint=/mnt/resource

    # Create and use swapfile on resource disk.
    ResourceDisk.EnableSwap=n

    # Size of the swapfile.
    ResourceDisk.SwapSizeMB=0

    # Comma-seperated list of mount options. See man(8) for valid options.
    ResourceDisk.MountOptions=None

    # Enable verbose logging (y|n)
    Logs.Verbose=y

    # Is FIPS enabled
    OS.EnableFIPS=n

    # Root device timeout in seconds.
    OS.RootDeviceScsiTimeout=300

    # If "None", the system default version is used.
    OS.OpensslPath=None

    # Set the path to SSH keys and configuration files
    OS.SshDir=/etc/ssh

    # If set, agent will use proxy server to access internet
    #HttpProxy.Host=None
    #HttpProxy.Port=None

    # Detect Scvmm environment, default is n
    # DetectScvmmEnv=n

    #
    # Lib.Dir=/var/lib/waagent

    #
    # DVD.MountPoint=/mnt/cdrom/secure

    #
    # Pid.File=/var/run/waagent.pid

    #
    # Extension.LogDir=/var/log/azure

    #
    # Home.Dir=/home

    # Enable RDMA management and set up, should only be used in HPC images
    # OS.EnableRDMA=y

    # Enable or disable goal state processing auto-update, default is enabled
    AutoUpdate.Enabled=n

    # Determine the update family, this should not be changed
    # AutoUpdate.GAFamily=Prod

    # Determine if the overprovisioning feature is enabled. If yes, hold extension
    # handling until inVMArtifactsProfile.OnHold is false.
    # Default is disabled
    # EnableOverProvisioning=n
beelesnik commented 7 years ago

For one of my test VM with dead walinuxagent

testdebian8 sergey.lozenkov # waagent -version WALinuxAgent-2.2.2 running on debian 8.8 Python: 3.4.2 Goal state agent: 2.2.2

I have enabled verbose logging. After that I see such behavior:

  1. I have old strings in my log: 2017/06/15 22:51:23.421042 INFO Activate resource disk 2017/06/15 22:51:23.451237 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/16 18:09:15.875572 INFO Provisioning already completed, skipping. 2017/06/16 18:09:15.884863 INFO Activate resource disk 2017/06/16 18:09:15.912334 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource]

  2. Have dead status of walinuxagent testdebian8 sergey.lozenkov # systemctl status walinuxagent ● walinuxagent.service - Microsft Azure Linux Agent Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled) Active: inactive (dead) testdebian8 sergey.lozenkov #

  3. I have tried to start walinuxagent and wait for minute testdebian8 sergey.lozenkov # systemctl start walinuxagent ^C

  4. I see that some strings added to waagent.log

2017/06/16 18:09:15.884863 INFO Activate resource disk 2017/06/16 18:09:15.912334 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/20 10:16:20.154482 INFO Provisioning already completed, skipping. 2017/06/20 10:16:20.170781 INFO Activate resource disk 2017/06/20 10:16:20.199828 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/20 10:23:22.087429 INFO Provisioning already completed, skipping. 2017/06/20 10:23:22.095544 INFO Activate resource disk 2017/06/20 10:23:22.113330 VERBOSE run cmd 'mount' 2017/06/20 10:23:22.136700 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource]

  1. Another attempt to start walinuxagent added same string 2017/06/16 18:09:15.875572 INFO Provisioning already completed, skipping. 2017/06/16 18:09:15.884863 INFO Activate resource disk 2017/06/16 18:09:15.912334 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/20 10:16:20.154482 INFO Provisioning already completed, skipping. 2017/06/20 10:16:20.170781 INFO Activate resource disk 2017/06/20 10:16:20.199828 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/20 10:23:22.087429 INFO Provisioning already completed, skipping. 2017/06/20 10:23:22.095544 INFO Activate resource disk 2017/06/20 10:23:22.113330 VERBOSE run cmd 'mount' 2017/06/20 10:23:22.136700 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource] 2017/06/20 10:25:06.176493 INFO Provisioning already completed, skipping. 2017/06/20 10:25:06.187864 INFO Activate resource disk 2017/06/20 10:25:06.204373 VERBOSE run cmd 'mount' 2017/06/20 10:25:06.233632 INFO Resource disk [/dev/sdb1] is already mounted [/mnt/resource]

And that is all.

And another question, why if I did not touch config and it has (# AutoUpdate.Enabled=y) I see that waagent could not get new version by automatic updates...

beelesnik commented 7 years ago

Yet another my test VM is ended with such string in waagent.log. As You can see walinuxagent kill itself and never start again. 2017/06/20 10:38:53.055050 VERBOSE Agent WALinuxAgent-2.2.13 loaded manifest from /var/lib/waagent/WALinuxAgent-2.2.13/HandlerManifest.json 2017/06/20 10:38:53.077214 VERBOSE Successfully loaded Agent WALinuxAgent-2.2.13 HandlerManifest.json: {'handlerManifest': {'reportHeartbeat': False, 'installCommand': '', 'rebootAfterInstall': False, 'enableCommand': 'python -u bin/WALinuxAgent-2.2.13-py2.7.egg -run-exthandlers', 'updateCommand': '', 'uninstallCommand': '', 'disableCommand': ''}, 'name': 'WALinuxAgent', 'version': 1.0} 2017/06/20 10:38:53.133992 VERBOSE Instantiating Agent WALinuxAgent-2.2.12 from disk 2017/06/20 10:38:53.145231 INFO Agent WALinuxAgent-2.2.2 forwarding signal 15 to WALinuxAgent-2.2.13 2017/06/20 11:01:58.965411 INFO Activate resource disk 2017/06/20 11:01:59.002772 VERBOSE run cmd 'mount' 2017/06/20 11:01:59.047799 INFO Examining partition table 2017/06/20 11:01:59.056929 VERBOSE run cmd 'blkid -o value -s PTTYPE /dev/sdb' 2017/06/20 11:01:59.137793 INFO GPT not detected, determining filesystem 2017/06/20 11:01:59.170816 VERBOSE run cmd 'blkid -o value -s TYPE /dev/sdb1' 2017/06/20 10:39:48.160101 INFO Mount resource disk [mount /dev/sdb1 /mnt/resource] 2017/06/20 10:39:48.220541 VERBOSE run cmd 'mount /dev/sdb1 /mnt/resource' 2017/06/20 10:39:48.293273 INFO Resource disk /dev/sdb is mounted at /mnt/resource with ext4 2017/06/20 10:40:00.593970 INFO Provisioning already completed, skipping. 2017/06/20 12:00:49.979667 INFO Activate resource disk 2017/06/20 12:00:50.008467 VERBOSE run cmd 'mount' 2017/06/20 12:00:50.055507 INFO Examining partition table 2017/06/20 12:00:50.077054 VERBOSE run cmd 'blkid -o value -s PTTYPE /dev/sdb' 2017/06/20 12:00:34.282794 INFO GPT not detected, determining filesystem 2017/06/20 12:00:34.335180 VERBOSE run cmd 'blkid -o value -s TYPE /dev/sdb1' 2017/06/20 12:00:34.398692 INFO Mount resource disk [mount /dev/sdb1 /mnt/resource] 2017/06/20 12:00:34.411053 VERBOSE run cmd 'mount /dev/sdb1 /mnt/resource' 2017/06/20 12:00:34.449575 INFO Resource disk /dev/sdb is mounted at /mnt/resource with ext4 2017/06/20 12:01:06.807027 INFO Provisioning already completed, skipping.

P.S. And I see that Goal state is 2.2.2 (in output of waagent -version ) because only working agent could dynamically download something new :)

brendandixon commented 7 years ago

@beelesnik Log lines such as:

2017/06/20 07:06:50.862248 INFO Agent WALinuxAgent-2.2.13 forwarding signal 15 to WALinuxAgent-2.2.13

Do not indicate the agent is killing itself. The agent runs as two processes: A parent daemon and a child process. The log line notes the parent forwarding the kill signal (15) to the child. That is normal and expected when the parent is asked to stop running.

Several things here:

Nothing here indicates a problem with the agent. It appears, instead, that the installation is not wholly correct. I hope this helps.