ChromeOS Version: 
R65-10323.44.0

Board:panther

What steps will reproduce the problem?
(1)run autotest script:enterprise_CFM_USBPeripheralHotplugStress.jabra410mic

log
---
timestamp between /var/log/message and test script log are not un sync.
How many hours difference between these 2?


https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/179774338-chromeos-test/chromeos1-row3-rack5-host2/enterprise_CFM_USBPeripheralHotplugStress.jabra410mic

/var/log/messages shows jabra comes up and never goes offline.
2018-02-27T14:30:33.337045+00:00 INFO kernel: [    0.648225] usb 1-2: new full-speed USB device number 2 using xhci_hcd
2018-02-27T14:30:33.337046+00:00 WARNING kernel: [    0.658679] atkbd serio0: GETID failed
2018-02-27T14:30:33.337047+00:00 WARNING kernel: [    0.687321] atkbd serio0: atkbd: SETLEDS failed
2018-02-27T14:30:33.337047+00:00 ERR kernel: [    0.687331] atkbd serio0: probe failed
2018-02-27T14:30:33.337048+00:00 INFO kernel: [    0.706336] usb 1-2: New USB device found, idVendor=0b0e, idProduct=0412
2018-02-27T14:30:33.337049+00:00 INFO kernel: [    0.706346] usb 1-2: New USB device strings: Mfr=0, Product=2, SerialNumber=3
2018-02-27T14:30:33.337051+00:00 INFO kernel: [    0.706355] usb 1-2: Product: Jabra SPEAK 410 USB
2018-02-27T14:30:33.337052+00:00 INFO kernel: [    0.706361] usb 1-2: SerialNumber: 501AA521D5D7x010900


script log
---------------
02/27 06:27:59.069 INFO |             servo:0529| Setting usb_mux_sel3 to dut_sees_usbkey
02/27 06:28:04.175 INFO |             servo:0529| Setting dut_hub1_rst1 to off  <<<<<<<<<<<<<<<<<<<<<<<<<<< poweroff usb port?


02/27 06:28:10.329 INFO |        server_job:0218| 	START	----	reboot	timestamp=1519741690	localtime=Feb 27 06:28:10	
02/27 06:28:10.330 INFO |        server_job:0218| 		GOOD	----	reboot.start	timestamp=1519741690	localtime=Feb 27 06:28:10	 <======reboot
02/27 06:28:22.115 WARNI|             utils:0925| run process timeout (10) fired on: /usr/bin/ssh -a -x   -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 22 chromeos1-row3-rack5-host2 "export LIBC_FATAL_STDERR_=1; if type \"logger\" > /dev/null 2>&1; then logger -tag \"autotest\" \"server[stack::wait_down|get_boot_id|run] -> ssh_run(if [ -f '/proc/sys/kernel/random/boot_id' ]; then cat '/proc/sys/kernel/random/boot_id'; else echo 'no boot_id available'; fi)\";fi; if [ -f '/proc/sys/kernel/random/boot_id' ]; then cat '/proc/sys/kernel/random/boot_id'; else echo 'no boot_id available'; fi"
02/27 06:28:30.407 INFO |        server_job:0218| 		GOOD	----	reboot.verify	timestamp=1519741710	localtime=Feb 27 06:28:30	
02/27 06:28:30.928 INFO |        server_job:0218| 	END GOOD	----	reboot	kernel=3.8.11	localtime=Feb 27 06:28:30	timestamp=1519741710	
02/27 06:28:30.934 INFO |remote_facade_fact:0242| Setup the connection to RPC server, with retries...
02/27 06:28:31.180 INFO |rpc_server_tracker:0276| Waiting for RPC server "multimedia_xmlrpc_server" shutdown
02/27 06:28:31.496 INFO |rpc_server_tracker:0284| Shut down RPC server.
02/27 06:28:31.751 INFO |rpc_server_tracker:0196| Waiting 90 seconds for XMLRPC server to start.
02/27 06:28:31.752 WARNI|             retry:0228| <class 'socket.error'>([Errno 111] Connection refused)
02/27 06:28:31.752 WARNI|             retry:0183| Retrying in 1.324637 seconds...
02/27 06:28:33.084 INFO |rpc_server_tracker:0208| XMLRPC server started successfully.
02/27 06:28:33.084 INFO |remote_facade_fact:0245| Start a job to save the log from the client.
02/27 06:28:33.085 INFO |remote_facade_fact:0202| Kill and join the previous log job.
02/27 06:28:34.093 WARNI|remote_facade_fact:0182| Retrying RPC 'cfm_main_screen.enroll_device'((), {}).
02/27 06:29:52.208 INFO |          autotest:0364| Installing autotest on chromeos1-row3-rack5-host2
02/27 06:29:52.208 INFO |          autotest:0369| Using installation dir /tmp/sysinfo/autoserv-xi5due
02/27 06:29:52.708 INFO |          autotest:0275| Got job repo url from host attributes: http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages
02/27 06:29:53.670 INFO |          packages:0190| Fetching client-autotest.tar.bz2 from http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages to /tmp/sysinfo/autoserv-xi5due/packages/client-autotest.tar.bz2
02/27 06:29:55.116 ERROR|             utils:0282| [stderr] 2018-02-27 06:29:54 URL:http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages/client-autotest.tar.bz2 [11964889/11964889] -> "/tmp/sysinfo/autoserv-xi5due/packages/client-autotest.tar.bz2" [1]
02/27 06:29:55.369 INFO |          packages:0207| Successfully fetched client-autotest.tar.bz2 from http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages/client-autotest.tar.bz2
02/27 06:29:56.409 INFO |          packages:0190| Fetching packages.checksum from http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages to /tmp/sysinfo/autoserv-xi5due/packages.checksum
02/27 06:29:57.301 ERROR|             utils:0282| [stderr] 2018-02-27 06:29:56 URL:http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages/packages.checksum [34957/34957] -> "/tmp/sysinfo/autoserv-xi5due/packages.checksum" [1]
02/27 06:29:57.591 INFO |          packages:0207| Successfully fetched packages.checksum from http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages/packages.checksum
02/27 06:29:58.695 ERROR|             utils:0282| [stderr] cat: /tmp/sysinfo/autoserv-xi5due/.checksum: No such file or directory
02/27 06:30:01.314 INFO |          autotest:0382| Installation of autotest completed using the packaging system.
02/27 06:30:04.301 INFO |          autotest:0275| Got job repo url from host attributes: http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages
02/27 06:30:05.224 INFO |          autotest:1003| Executing /tmp/sysinfo/autoserv-xi5due/bin/autotest /tmp/sysinfo/autoserv-xi5due/control phase 0
02/27 06:30:06.544 INFO |          autotest:1369| Entered autotestd_monitor.
02/27 06:30:06.544 INFO |          autotest:1369| Finished launching tail subprocesses.
02/27 06:30:06.545 INFO |          autotest:1369| Finished waiting on autotestd to start.
02/27 06:30:06.568 INFO |        server_job:0218| 	START	----	----	timestamp=1519741805	localtime=Feb 27 06:30:05	
02/27 06:30:06.646 INFO |        server_job:0218| 		GOOD	----	sysinfo.iteration.before	timestamp=1519741805	localtime=Feb 27 06:30:05	
02/27 06:30:06.656 INFO |        server_job:0218| 	END GOOD	----	----	timestamp=1519741805	localtime=Feb 27 06:30:05	
02/27 06:30:06.678 INFO |          autotest:1369| Got lock of exit_code_file.
02/27 06:30:06.678 INFO |          autotest:1369| Released lock of exit_code_file and closed it.
02/27 06:30:08.676 INFO |          autotest:1369| Killing child processes.
02/27 06:30:08.686 INFO |          autotest:1088| Client complete
02/27 06:30:10.143 INFO |             servo:0529| Setting dut_hub1_rst1 to on <============================================= power usb port on?


02/27 06:30:18.531 INFO |          autotest:0275| Got job repo url from host attributes: http://172.27.215.245:8082/static/panther-release/R65-10323.44.0/autotest/packages
02/27 06:30:19.374 INFO |          autotest:1003| Executing /tmp/sysinfo/autoserv-xi5due/bin/autotest /tmp/sysinfo/autoserv-xi5due/control phase 0
02/27 06:30:20.679 INFO |        server_job:0218| 	START	----	----	timestamp=1519741819	localtime=Feb 27 06:30:19	
02/27 06:30:20.679 INFO |          autotest:1369| Entered autotestd_monitor.
02/27 06:30:20.679 INFO |          autotest:1369| Finished launching tail subprocesses.
02/27 06:30:20.680 INFO |          autotest:1369| Finished waiting on autotestd to start.
02/27 06:30:20.680 INFO |        server_job:0218| 		GOOD	----	sysinfo.iteration.after	timestamp=1519741819	localtime=Feb 27 06:30:19	
02/27 06:30:20.684 INFO |        server_job:0218| 	END GOOD	----	----	timestamp=1519741819	localtime=Feb 27 06:30:19	
02/27 06:30:20.706 INFO |          autotest:1369| Got lock of exit_code_file.
02/27 06:30:20.706 INFO |          autotest:1369| Released lock of exit_code_file and closed it.
02/27 06:30:22.717 INFO |          autotest:1369| Killing child processes.
02/27 06:30:22.734 INFO |          autotest:1088| Client complete
02/27 06:30:23.931 WARNI|              test:0637| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_USBPeripheralHotplugStress/enterprise_CFM_USBPeripheralHotplugStress.py", line 147, in run_once
    self._check_peripherals(peripheral_whitelist_dict, False)
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_USBPeripheralHotplugStress/enterprise_CFM_USBPeripheralHotplugStress.py", line 117, in _check_peripherals
    self.cfm_facade.get_mic_devices)
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_USBPeripheralHotplugStress/enterprise_CFM_USBPeripheralHotplugStress.py", line 87, in _check_peripheral
    raise error.TestFail('%s should not be detected.' % device_type)
TestFail: Microphone should not be detected.  <<<<<<<<<<<<<