TS-XE8.0TL/R5 - CPU Utilization= 100%

[NikG]

Hi all!

We are having an issue with "CPU Utilization= 100%" since around Feb 10, 2015. It appears some sort of update might of been automatically installed then. The "CPU Utilization= 100%" makes it unable to access the admin webpage and will eventually require the NAS to be restarted to access the shares.

Here is the log from around the update
Feb 10 10:04:02 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 10:04:03 NS02 last message repeated 2 times
Feb 10 10:04:03 NS02 S40B_update_notifications.sh: checking and registering to cron...
Feb 10 10:04:05 NS02 S40B_update_notifications.sh: old xml file found. deleting...
Feb 10 10:04:07 NS02 S40B_update_notifications.sh: starting f/w cheking process ...
Feb 10 10:04:13 NS02 S40B_update_notifications.sh: step1 result=1
Feb 10 10:04:13 NS02 S40B_update_notifications.sh: step2 result=1
Feb 10 10:04:14 NS02 S40B_update_notifications.sh: notifing lcd...
Feb 10 10:04:15 NS02 errormon[1783]: Information situation detected! New Firmware I52Available
Feb 10 10:46:13 NS02 linkstation: [Success] Sync to ntp server
Feb 10 15:21:10 NS02 kernelmon: cmd=micon_interrupts
Feb 10 16:41:40 NS02 update_notifications.sh: Not boot process now. cannot register to cron...
Feb 10 16:41:40 NS02 update_notifications.sh: old xml file found. deleting...
Feb 10 16:41:42 NS02 update_notifications.sh: starting f/w cheking process ...
Feb 10 16:41:55 NS02 update_notifications.sh: step1 result=1
Feb 10 16:41:55 NS02 update_notifications.sh: step2 result=1
Feb 10 16:41:56 NS02 update_notifications.sh: notifing lcd...
Feb 10 16:43:41 NS02 update_notifications.sh: cheking process...
Feb 10 16:43:41 NS02 update_notifications.sh: locking process...
Feb 10 16:43:41 NS02 update_notifications.sh: not iscsi model. continue.
Feb 10 16:43:41 NS02 update_notifications.sh: old xml file found. deleting...
Feb 10 16:43:43 NS02 update_notifications.sh: starting f/w cheking process ...
Feb 10 16:43:58 NS02 update_notifications.sh: step1 result=1
Feb 10 16:43:58 NS02 update_notifications.sh: step2 result=1
Feb 10 16:46:01 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 16:46:02 NS02 last message repeated 2 times
Feb 10 16:46:02 NS02 S40B_update_notifications.sh: checking and registering to cron...
Feb 10 16:46:02 NS02 S40B_update_notifications.sh: old xml file found. deleting...
Feb 10 16:46:04 NS02 S40B_update_notifications.sh: starting f/w cheking process ...
Feb 10 16:46:07 NS02 S40B_update_notifications.sh: step1 result=1
Feb 10 16:46:07 NS02 S40B_update_notifications.sh: step2 result=1
Feb 10 16:46:08 NS02 S40B_update_notifications.sh: notifing lcd...
Feb 10 16:51:39 NS02 update_notifications.sh: file cheking...
Feb 10 16:54:24 NS02 update_notifications.sh: checking file is correct... success.
Feb 10 16:54:24 NS02 update_notifications.sh: starting file extracting process...
Feb 10 17:01:25 NS02 update_notifications.sh: extracting file... success.
Feb 10 17:01:26 NS02 update_notifications.sh: copying file...
Feb 10 17:02:43 NS02 update_notifications.sh: rebooting system...
Feb 10 17:03:18 NS02 errormon[1783]: Information situation detected! F/W          I25Updating
Feb 10 17:03:36 NS02 errormon[1783]: Information situation cleared! F/W          I25Updating
Feb 10 17:03:51 NS02 errormon[1783]: exit.: sig=15
Feb 10 17:15:24 NS02 linkstation: Started logchkd
Feb 10 17:15:25 NS02 errormon[1776]: errormon-ver.2.00 started
Feb 10 17:15:25 NS02 linkstation: Started errormon
Feb 10 17:15:25 NS02 linkstation: Started kernelmon
Feb 10 17:15:26 NS02 kernelmon: cmd=SATA 0 plugged
Feb 10 17:15:26 NS02 kernelmon: cmd=SATA 1 plugged
Feb 10 17:15:27 NS02 kernelmon: cmd=SATA 2 plugged
Feb 10 17:15:27 NS02 kernelmon: cmd=SATA 3 plugged
Feb 10 17:15:28 NS02 kernelmon: cmd=lanact 100 full eth0
Feb 10 17:15:44 NS02 start_data_array.sh: IS_CHECK_ARRAY_STAUS 0
Feb 10 17:15:44 NS02 hdd_raid_syncspeed.sh: /dev/md2 (raid5) sync speed max is setted to 3000
Feb 10 17:15:44 NS02 start_data_array.sh: *** diskinfo guess ***
Feb 10 17:15:47 NS02 start_data_array.sh:  >check array's mount point
Feb 10 17:15:48 NS02 start_data_array.sh:  >check normal state
Feb 10 17:15:48 NS02 start_data_array.sh:   * DISKINFO_GUESS status check and Restore *
Feb 10 17:15:48 NS02 start_data_array.sh:   * The status is normal? *
Feb 10 17:15:48 NS02 start_data_array.sh:    diskinfo guess is not exist normal state.
Feb 10 17:15:48 NS02 start_data_array.sh:    skip normal status checking.
Feb 10 17:15:48 NS02 start_data_array.sh: *** compaire ***
Feb 10 17:15:48 NS02 start_data_array.sh:  array1=raid5 ... [OK]
Feb 10 17:15:48 NS02 start_data_array.sh:  array2=off ... [skip]
Feb 10 17:15:48 NS02 start_data_array.sh:  disk1=array1 ... [OK]
Feb 10 17:15:48 NS02 start_data_array.sh:  disk2=array1 ... [OK]
Feb 10 17:15:48 NS02 start_data_array.sh:  disk3=array1 ... [OK]
Feb 10 17:15:48 NS02 start_data_array.sh:  disk4=array1 ... [OK]
Feb 10 17:15:48 NS02 start_data_array.sh: diskinfo ... [OK]
Feb 10 17:15:57 NS02 linkstation: Started inetd
Feb 10 17:16:41 NS02 linkstation: cron.sh : logrotate.status deleted.
Feb 10 17:16:41 NS02 checkconfig: diskmon_exec.sh schedule added
Feb 10 17:16:45 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 17:16:46 NS02 twonky: Media Server script is begun. type=start
Feb 10 17:16:46 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 17:16:46 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 17:16:46 NS02 S40B_update_notifications.sh: checking and registering to cron...
Feb 10 17:16:46 NS02 twonky: Media Server setting is off
Feb 10 17:16:48 NS02 S40B_update_notifications.sh: starting f/w cheking process ...
Feb 10 17:16:51 NS02 S40B_update_notifications.sh: step1 result=0
Feb 10 17:16:51 NS02 S40B_update_notifications.sh: version_is_latest
Feb 10 17:16:51 NS02 S40B_update_notifications.sh: deleting from lcd...
Feb 10 17:16:52 NS02 splx_buffalo.sh: TMNAS is not supported on this model
Feb 10 17:16:55 NS02 root: linkstation
Feb 10 17:16:59 NS02 hdd_raid_syncspeed.sh: /dev/md0 sync speed max is setted to 50000
Feb 10 17:16:59 NS02 hdd_raid_syncspeed.sh: /dev/md1 sync speed max is setted to 50000
Feb 10 17:16:59 NS02 hdd_raid_syncspeed.sh: /dev/md10 sync speed max is setted to 50000
Feb 10 17:17:00 NS02 hdd_raid_syncspeed.sh: /dev/md2 (raid5) sync speed max is setted to 30000
Feb 10 17:30:02 NS02 nas_status.sh: loadavg= 1.75 1.32 0.87 : CPU Utilization= 91%
Feb 10 18:00:02 NS02 nas_status.sh: loadavg= 1.48 1.25 1.13 : CPU Utilization= 97%
Feb 10 18:30:02 NS02 nas_status.sh: loadavg= 1.22 1.19 1.18 : CPU Utilization= 98%
Feb 10 19:00:01 NS02 nas_status.sh: loadavg= 1.15 1.24 1.24 : CPU Utilization= 99%
Feb 10 19:30:01 NS02 nas_status.sh: loadavg= 1.14 1.20 1.19 : CPU Utilization= 99%
Feb 10 20:00:01 NS02 nas_status.sh: loadavg= 1.36 1.25 1.20 : CPU Utilization= 99%
Feb 10 20:30:01 NS02 nas_status.sh: loadavg= 1.08 1.16 1.18 : CPU Utilization= 99%
Feb 10 21:00:01 NS02 nas_status.sh: loadavg= 1.17 1.19 1.18 : CPU Utilization= 99%
Feb 10 21:30:01 NS02 nas_status.sh: loadavg= 1.31 1.25 1.19 : CPU Utilization= 99%
Feb 10 22:00:02 NS02 nas_status.sh: loadavg= 1.28 1.27 1.19 : CPU Utilization= 100%
Feb 10 22:16:02 NS02 S40B_update_notifications.sh: deleting old settings...
Feb 10 22:16:02 NS02 last message repeated 2 times
Feb 10 22:16:02 NS02 S40B_update_notifications.sh: checking and registering to cron...
Feb 10 22:16:02 NS02 S40B_update_notifications.sh: old xml file found. deleting...
Feb 10 22:16:03 NS02 S40B_update_notifications.sh: starting f/w cheking process ...
Feb 10 22:16:05 NS02 S40B_update_notifications.sh: step1 result=0
Feb 10 22:16:05 NS02 S40B_update_notifications.sh: version_is_latest
Feb 10 22:16:05 NS02 S40B_update_notifications.sh: deleting from lcd...
Feb 10 22:30:01 NS02 nas_status.sh: loadavg= 1.10 1.24 1.21 : CPU Utilization= 100%
Feb 10 23:00:01 NS02 nas_status.sh: loadavg= 1.09 1.20 1.18 : CPU Utilization= 100%
Feb 10 23:30:01 NS02 nas_status.sh: loadavg= 1.16 1.11 1.10 : CPU Utilization= 100%
Feb 11 00:00:02 NS02 nas_status.sh: loadavg= 1.16 1.16 1.16 : CPU Utilization= 100%
Feb 11 00:30:01 NS02 nas_status.sh: loadavg= 2.24 2.19 1.98 : CPU Utilization= 100%
Feb 11 01:00:01 NS02 nas_status.sh: loadavg= 2.27 2.20 2.14 : CPU Utilization= 100%
Feb 11 01:30:02 NS02 nas_status.sh: loadavg= 2.13 2.34 2.33 : CPU Utilization= 100%
Feb 11 02:00:01 NS02 nas_status.sh: loadavg= 2.06 2.07 2.15 : CPU Utilization= 100%
Feb 11 02:30:01 NS02 nas_status.sh: loadavg= 2.04 2.11 2.14 : CPU Utilization= 100%
Feb 11 03:00:01 NS02 nas_status.sh: loadavg= 2.00 2.06 2.10 : CPU Utilization= 100%
Feb 11 03:30:01 NS02 nas_status.sh: loadavg= 2.04 2.06 2.08 : CPU Utilization= 100%
Feb 11 04:00:01 NS02 nas_status.sh: loadavg= 2.37 2.19 2.12 : CPU Utilization= 100%
Feb 11 04:30:01 NS02 nas_status.sh: loadavg= 2.39 2.33 2.20 : CPU Utilization= 100%
Feb 11 05:00:01 NS02 nas_status.sh: loadavg= 2.09 2.23 2.32 : CPU Utilization= 100%
Feb 11 05:30:01 NS02 nas_status.sh: loadavg= 2.09 2.22 2.26 : CPU Utilization= 100%
Feb 11 06:00:01 NS02 nas_status.sh: loadavg= 2.42 2.32 2.20 : CPU Utilization= 100%
Feb 11 06:30:01 NS02 nas_status.sh: loadavg= 2.21 2.30 2.25 : CPU Utilization= 100%
Feb 11 07:00:01 NS02 nas_status.sh: loadavg= 2.16 2.14 2.19 : CPU Utilization= 100%
Feb 11 07:30:01 NS02 nas_status.sh: loadavg= 2.42 2.25 2.20 : CPU Utilization= 100%
Feb 11 08:00:01 NS02 nas_status.sh: loadavg= 2.79 2.58 2.43 : CPU Utilization= 100%
Feb 11 08:30:01 NS02 nas_status.sh: loadavg= 2.62 2.61 2.53 : CPU Utilization= 100%
Feb 11 09:00:01 NS02 nas_status.sh: loadavg= 4.18 4.26 3.59 : CPU Utilization= 100%
Feb 11 09:30:01 NS02 nas_status.sh: loadavg= 2.90 3.53 3.72 : CPU Utilization= 100%
Feb 11 10:00:01 NS02 nas_status.sh: loadavg= 2.81 2.90 3.08 : CPU Utilization= 100%
Feb 11 10:30:01 NS02 nas_status.sh: loadavg= 2.54 2.76 2.88 : CPU Utilization= 100%

Here are some logs after the last reboot, just to show how quickly the CPU ramps up
Jun 10 12:25:53 NS02 linkstation: Started logchkd
Jun 10 12:25:53 NS02 errormon[1818]: errormon-ver.2.00 started
Jun 10 12:25:53 NS02 linkstation: Started errormon
Jun 10 12:25:53 NS02 linkstation: Started kernelmon
Jun 10 12:25:54 NS02 kernelmon: cmd=SATA 0 plugged
Jun 10 12:25:55 NS02 kernelmon: cmd=SATA 1 plugged
Jun 10 12:25:56 NS02 kernelmon: cmd=SATA 2 plugged
Jun 10 12:25:56 NS02 kernelmon: cmd=SATA 3 plugged
Jun 10 12:25:57 NS02 kernelmon: cmd=lanact 100 full eth0
Jun 10 12:26:12 NS02 start_data_array.sh: IS_CHECK_ARRAY_STAUS 0
Jun 10 12:26:12 NS02 hdd_raid_syncspeed.sh: /dev/md2 (raid5) sync speed max is setted to 3000
Jun 10 12:26:12 NS02 start_data_array.sh: *** diskinfo guess ***
Jun 10 12:26:15 NS02 start_data_array.sh:  >check array's mount point
Jun 10 12:26:15 NS02 start_data_array.sh:  >check normal state
Jun 10 12:26:16 NS02 start_data_array.sh:   * DISKINFO_GUESS status check and Restore *
Jun 10 12:26:16 NS02 start_data_array.sh:   * The status is normal? *
Jun 10 12:26:16 NS02 start_data_array.sh:    diskinfo guess is not exist normal state.
Jun 10 12:26:16 NS02 start_data_array.sh:    skip normal status checking.
Jun 10 12:26:16 NS02 start_data_array.sh: *** compaire ***
Jun 10 12:26:16 NS02 start_data_array.sh:  array1=raid5 ... [OK]
Jun 10 12:26:16 NS02 start_data_array.sh:  array2=off ... [skip]
Jun 10 12:26:16 NS02 start_data_array.sh:  disk1=array1 ... [OK]
Jun 10 12:26:16 NS02 start_data_array.sh:  disk2=array1 ... [OK]
Jun 10 12:26:16 NS02 start_data_array.sh:  disk3=array1 ... [OK]
Jun 10 12:26:16 NS02 start_data_array.sh:  disk4=array1 ... [OK]
Jun 10 12:26:16 NS02 start_data_array.sh: diskinfo ... [OK]
Jun 10 12:26:27 NS02 linkstation: Started inetd
Jun 10 12:26:49 NS02 linkstation: cron.sh : logrotate.status is fine.
Jun 10 12:26:54 NS02 S40B_update_notifications.sh: deleting old settings...
Jun 10 12:26:54 NS02 twonky: Media Server script is begun. type=start
Jun 10 12:26:54 NS02 S40B_update_notifications.sh: deleting old settings...
Jun 10 12:26:55 NS02 S40B_update_notifications.sh: deleting old settings...
Jun 10 12:26:55 NS02 S40B_update_notifications.sh: checking and registering to cron...
Jun 10 12:26:55 NS02 twonky: Media Server setting is off
Jun 10 12:26:58 NS02 root: linkstation
Jun 10 12:27:02 NS02 hdd_raid_syncspeed.sh: /dev/md0 sync speed max is setted to 50000
Jun 10 12:27:03 NS02 hdd_raid_syncspeed.sh: /dev/md1 sync speed max is setted to 50000
Jun 10 12:27:03 NS02 hdd_raid_syncspeed.sh: /dev/md10 sync speed max is setted to 50000
Jun 10 12:27:03 NS02 hdd_raid_syncspeed.sh: /dev/md2 (raid5) sync speed max is setted to 30000
Jun 10 12:27:04 NS02 S40B_update_notifications.sh: starting f/w cheking process ...
Jun 10 12:27:07 NS02 S40B_update_notifications.sh: step1 result=0
Jun 10 12:27:07 NS02 S40B_update_notifications.sh: version_is_latest
Jun 10 12:27:07 NS02 S40B_update_notifications.sh: deleting from lcd...
Jun 10 12:30:02 NS02 nas_status.sh: loadavg= 1.65 1.20 0.53 : CPU Utilization= 76%
Jun 10 13:00:02 NS02 nas_status.sh: loadavg= 1.52 1.48 1.33 : CPU Utilization= 96%
Jun 10 13:28:04 NS02 mdscan: mdscan stop
Jun 10 13:28:04 NS02 linkstation: cron.sh : logrotate.status is fine.
Jun 10 13:30:01 NS02 nas_status.sh: loadavg= 1.80 1.73 1.54 : CPU Utilization= 98%
Jun 10 14:00:01 NS02 nas_status.sh: loadavg= 1.69 1.63 1.59 : CPU Utilization= 98%
Jun 10 14:30:02 NS02 nas_status.sh: loadavg= 1.39 1.48 1.55 : CPU Utilization= 99%
Jun 10 14:48:18 NS02 kernelmon: cmd=micon_interrupts
Jun 10 14:48:26 NS02 last message repeated 4 times
Jun 10 15:00:02 NS02 nas_status.sh: loadavg= 1.37 1.52 1.54 : CPU Utilization= 99%
Jun 10 15:30:02 NS02 nas_status.sh: loadavg= 1.41 1.35 1.42 : CPU Utilization= 99%
Jun 10 16:00:01 NS02 nas_status.sh: loadavg= 1.92 1.74 1.58 : CPU Utilization= 99%
Jun 10 16:30:01 NS02 nas_status.sh: loadavg= 1.50 1.47 1.45 : CPU Utilization= 99%
Jun 10 17:00:01 NS02 nas_status.sh: loadavg= 1.34 1.27 1.31 : CPU Utilization= 99%
Jun 10 17:30:01 NS02 nas_status.sh: loadavg= 1.42 1.32 1.27 : CPU Utilization= 100%
Jun 10 18:00:01 NS02 nas_status.sh: loadavg= 1.15 1.14 1.16 : CPU Utilization= 100%
Jun 10 18:30:01 NS02 nas_status.sh: loadavg= 1.14 1.18 1.17 : CPU Utilization= 100%
Jun 10 19:00:01 NS02 nas_status.sh: loadavg= 1.05 1.16 1.17 : CPU Utilization= 100%
Jun 10 19:30:01 NS02 nas_status.sh: loadavg= 1.18 1.25 1.19 : CPU Utilization= 100%
Jun 10 20:00:01 NS02 nas_status.sh: loadavg= 1.13 1.13 1.13 : CPU Utilization= 100%
Jun 10 20:30:01 NS02 nas_status.sh: loadavg= 1.40 1.24 1.19 : CPU Utilization= 100%
Jun 10 21:00:02 NS02 nas_status.sh: loadavg= 1.14 1.22 1.20 : CPU Utilization= 100%
Jun 10 21:30:01 NS02 nas_status.sh: loadavg= 1.40 1.27 1.20 : CPU Utilization= 100%
Jun 10 22:00:01 NS02 nas_status.sh: loadavg= 1.23 1.21 1.18 : CPU Utilization= 100%
Jun 10 22:30:02 NS02 nas_status.sh: loadavg= 1.19 1.22 1.18 : CPU Utilization= 100%
Jun 10 23:00:02 NS02 nas_status.sh: loadavg= 1.09 1.22 1.17 : CPU Utilization= 100%
Jun 10 23:30:02 NS02 nas_status.sh: loadavg= 1.23 1.17 1.17 : CPU Utilization= 100%
Jun 11 00:00:02 NS02 nas_status.sh: loadavg= 1.11 1.21 1.19 : CPU Utilization= 100%
Jun 11 00:30:01 NS02 nas_status.sh: loadavg= 2.14 2.13 2.02 : CPU Utilization= 100%

I have been looking around for a couple weeks and haven't seen anybody else report this issue. We are looking for some way to get this NAS back to normal.

Thanks,
Nik

[mpitac]

Do you have the solution? I have the same problem. :(

[NikG]

Nope. I was told in my ticket I opened with Buffalo that I needed the latest firmware at the time and they closed my ticket without verifying that it resolved the issue. That didn't resolve the issue and I couldn't find anybody else that was reporting the issue.

We ended up trashing it and going to a cloud storage