WARNING ExtHandler Failed to decode event file: not well-formed (invalid token)

[johanburati]

Describe the bug

We keeps getting these warnings in waagent.log:

2019/01/25 11:34:21.722534 WARNING ExtHandler Failed to decode event file: not well-formed (invalid token): line 1, column 1
2019/01/25 11:49:22.864358 WARNING ExtHandler Failed to decode event file: not well-formed (invalid token): line 1, column 1
2019/01/25 12:04:24.065328 WARNING ExtHandler Failed to decode event file: not well-formed (invalid token): line 1, column 1
2019/01/25 12:19:25.349251 WARNING ExtHandler Failed to decode event file: not well-formed (invalid token): line 1, column 1
2019/01/25 12:34:26.597335 WARNING ExtHandler Failed to decode event file: not well-formed (invalid token): line 1, column 1

We checked the /var/lib/waagent/events/ directory but could not see any files in it.

I could see the OMS agent log is creating files in this folder but those files have been removed:

2019/01/25 12:28:38 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548415718211397.tld
2019/01/25 12:28:39 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548415719623161.tld
2019/01/25 12:33:38 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548416018237343.tld
2019/01/25 12:33:38 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548416018249641.tld
2019/01/25 12:33:38 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548416018257921.tld
2019/01/25 12:34:39 [Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux-1.8.11] /var/lib/waagent/events/1548416079803394.tld

Distro and WALinuxAgent details (please complete the following information):**

• Distro and Version: RHEL 7,4
• WALinuxAgent version:```
  2019/01/25 11:28:10.166261 INFO Azure Linux Agent Version:2.2.18
  2019/01/25 11:28:21.194402 INFO ExtHandler WALinuxAgent-2.2.34 running as process 1099

Additional context

I guess some files, maybe the ones generated by the OMS agent are malformed, still investigating.

[johanburati]

I have collected files in the events folder and was able to reproduce the issue.

# ls -l  1548850633269799.tld
-rw-r--r--. 1 root root 7620 Jan 30 23:19 1548850633269799.tld

# cat 1548850633269799.tld
 {
            "eventId": 1,
            "providerId": "69B669B9-4AF8-4C50-BDC4-6006FA76E975",
            "parameters": [
                        {
                        "name": "Name",
                        "value": "Microsoft.EnterpriseCloud.Monitoring.OmsAgentForLinux"
                },
                        {

            			"name": "Version",
            			"value": "1.8.11"
             		},

                        {
                        "name": "Operation",
                        "value": "DscPerformConsistency"
                },
                        {
                        "name": "OperationSuccess",
                        "value": false
                },
                        {
                        "name": "Message",
                        "value": "/opt/omi/bin/omicli: result: MI_RESULT_FAILED\n/opt/omi/bin/omicli: result: Failed to apply the configuration.  These resources produced errors: [MSFT_nxOMSAutomationWorkerResource]AutoRegister01\n\n---LOG---\n2019/01/30 13:00:35: WARNING: null(0): EventId=2 Priority=WARNING Job A7FC6963-6837-4FC3-BF46-59410045680C : PerformRequiredConfigurationChecks DSC operation completed in 34.4137 seconds.\n2019/01/30 13:15:01: WARNING: null(0): EventId=2 Priority=WARNING Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : Starting PerformRequiredConfigurationChecks DSC operation.\n2019/01/30 13:15:25: WARNING: null(0): EventId=2 Priority=WARNING Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : \nDisplaying messages from built-in DSC resources:\n\t WMI channel 1 \n\t ResourceID:  \n\t Message : [ZNLWENDMYSQL52]:                            [] Starting consistency engine.\n2019/01/30 13:15:25: WARNING: null(0): EventId=2 Priority=WARNING Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : \nDisplaying messages from built-in DSC resources:\n\t WMI channel 1 \n\t ResourceID:  \n\t Message : [ZNLWENDMYSQL52]:                            [] A pending configuration exists. DSC will process a set request on the pending configuration.\n2019/01/30 13:15:26: INFO: Scripts/nxOMSPlugin.pyc(114):\nOMSAgent is multi-homed and resource is updating workspace 217c5ff1-de1d-41f0-870d-5bbdd5e02e74\n2019/01/30 13:15:26: INFO: Scripts/nxOMSSyslog.pyc(56):\nConfig file is /etc/opt/omi/conf/omsconfig/rsyslog-oms.conf.\n2019/01/30 13:15:26: INFO: Scripts/nxOMSSyslog.pyc(189):\nSuccessfully read /etc/rsyslog.d/95-omsagent.conf.\n2019/01/30 13:15:26: INFO: Scripts/nxOMSSyslog.pyc(458):\nSuccesfully read /etc/opt/microsoft/omsagent/217c5ff1-de1d-41f0-870d-5bbdd5e02e74/conf/omsagent.d/syslog.conf for syslog port.\n2019/01/30 13:15:26: INFO: Scripts/nxOMSPerfCounter.pyc(40):\nConfiguration is in a workspace-specific path; resource is updating workspace 217c5ff1-de1d-41f0-870d-5bbdd5e02e74\n2019/01/30 13:15:26: INFO: Scripts/nxOMSPerfCounter.pyc(302):\nRead omsagent configuration /etc/opt/microsoft/omsagent/217c5ff1-de1d-41f0-870d-5bbdd5e02e74/conf/omsagent.conf.\n2019/01/30 13:15:26: INFO: Scripts/nxOMSPerfCounter.pyc(302):\nRead omsagent configuration /etc/opt/microsoft/omsagent/217c5ff1-de1d-41f0-870d-5bbdd5e02e74/conf/omsagent.conf.\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nUpdatesEnabled is True; AutomationWorkerEnabled is True\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nnxautomation was found on the system\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to detect instance of worker manager\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nrunning version is: 0.0\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nlatest available version is: 1.6.3.0\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nTest_Marshall returned [-1]: worker manager isn't running or is not latest\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nnxautomation was found on the system\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nNo old worker process to terminate\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nKilling the instance of worker manager already running\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nNo process to terminate\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to detect instance of worker manager\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\nNo worker manager processes to be killed\n2019/01/30 13:15:26: INFO: Scripts/nxOMSAutomationWorker.pyc(762):\nFailed to read nxautomation user processes\n2019/01/30 13:15:26: DEBUG: Scripts/nxOMSAutomationWorker.pyc(762):\noms.conf file was written\n2019/01/30 13:15:29: ERROR: Scripts/nxOMSAutomationWorker.pyc(762):\nSet_Marshall returned [-1] with following error: Traceback (most recent call last):\n  File "Scripts/nxOMSAutomationWorker.py", line 151, in Set_Marshall\n    + stderr + "\n" + stdout)\nException: Linux Hybrid Worker registration failed: Return code 1 :Traceback (most recent call last):\n  File "/opt/microsoft/omsconfig/modules/nxOMSAutomationWorker/DSCResources/MSFT_nxOMSAutomationWorkerResource/automationworker/scripts/register_oms.py", line 447, in <module>\n    main(sys.argv[1:])\n  File "/opt/microsoft/omsconfig/modules/nxOMSAutomationWorker/DSCResources/MSFT_nxOMSAutomationWorkerResource/automationworker/scripts/register_oms.py", line 426, in main\n    azure_resource_id, test_mode, platform_update_domain, tags)\n  File "/opt/microsoft/omsconfig/modules/nxOMSAutomationWorker/DSCResources/MSFT_nxOMSAutomationWorkerResource/automationworker/scripts/register_oms.py", line 202, in register\n    raise Exception("Unable to register [status_code=" + str(response.status_code) + "]")\nException: Unable to register [status_code=400]\n\n\n\n2019/01/30 13:15:29: ERROR: null(0): EventId=1 Priority=ERROR Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : \nThis event indicates that failure happens when LCM is processing the configuration. ErrorId is 1. ErrorDetail is The SendConfigurationApply function did not succeed.. ResourceId is [MSFT_nxOMSAutomationWorkerResource]AutoRegister01 and SourceInfo is null. ErrorMessage is A general error occurred, not covered by a more specific error code.. The related ResourceID is [MSFT_nxOMSAutomationWorkerResource]AutoRegister01..\n2019/01/30 13:15:30: ERROR: null(0): EventId=1 Priority=ERROR Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : \nDSC Engine Error : \n\t Error Message Failed to apply the configuration.  These resources produced errors: [MSFT_nxOMSAutomationWorkerResource]AutoRegister01 \n\tError Code : 1 \n2019/01/30 13:15:30: WARNING: null(0): EventId=2 Priority=WARNING Job 821EF6A7-77C4-46A3-8BCA-9C8A6A25F324 : \nDisplaying messages from built-in DSC resources:\n\t WMI channel 1 \n\t ResourceID:  \n\t Message : [ZNLWENDMYSQL52]:                            [] Consistency check completed.\n"
                },
                        {
                        "name": "Duration",
                        "value": 300000
                }
            ]
            }
			
	```

# cat 1548850633269799.tld | python -m json.tool
Expecting , delimiter: line 25 column 4621 (char 5382)

The file is generated by the OmsAgentForLinux extension and is not a properly formatted json file.

I have opened an issue microsoft/OMS-Agent-for-Linux#873

[vrdmr]

@johanburati - I've also created an issue in the extensions repo for the OMSAgent team to take a look at. I'll close this issue from our end. Thanks.

[johanburati]

Anyone interested, please refer to the report at microsoft/OMS-Agent-for-Linux#873, I will keep posting update there.