Guest User!

You are not Sophos Staff.

Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 1 reply
  • Subscribers 6 subscribers
  • Views 4367 views
  • Users 0 members are here
Options
Suggested
This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

SAV Mac Home Edition, v8 & v9: Deadlock in SAV On Access Scanning on laptops with Time Machine

ChrisJEChandler

Hi All,

   I've been reluctant to post this message until I was pretty confident that Sophos in access scanning is the problem. However, I am now pretty sure that there is a weird deadlock caused when 3 things happen at the same time on a laptop using the mobile Time Machine mode. I'm also pretty sure this doesn't happen with desktop (eg Mac Mini) computers. I am experiencing this with both SAV 9, on OS X 10.8.5. on all computers, but I also saw this with SAV 8.3 (or whatever it was) before I upgraded to SAV 9 in an attempt to avoid the problem. Searching Google shows people had this problem with OS X 10.7 with SAV 8 or earlier as well, but there aren't a lot of posts

1) Download large iPhone application in iTunes 11.x. It's possible that synchronising the iPhone (via USB - haven't tried WiFi) is also a factor.

2) Time Machine starts a mobile backup, specifially creating a snapshot. You'll see the kernel: nspace-handler-set-snapshot-time: <time_t> message in the console log as the chaos starts.

3) On Access scanning is enabled.

   The symptoms is that the processes on the computer slowly start to lock up. After a while, everything stops responding, and it's not possible to start a new process. When this happens, you have to press the power switch.

Work-arounds:

1) If you have a root shell window already open (logging in or sudo as root doesn't work, either locally or via ssh - the login hangs) shutdown -r now will eventually reboot your computer

2) Sometimes, unplugging the iPhone unjams everything and all returns to normal.

3) Configure SAV On-Access scanning to exclude:

/Users/<UserID>/Music/iTunes/Mobile Applications/Downloads (or whever iTunes is downloading applications to in your computer). This seems to work always, but it's also rather silly to exclude virus-checking on dlownloaded files, even if they are being signed and verified by Apple

   When this happens, if you are able to shutdown the computer, you can see chaos in SAV's kernel extension around the time it all happens, with ENOMEM errors etc. being reported and ignored and eventually reporting a corrupt file.

   Look for the "vnode" line: (I had to remove what I think are unrelated error messages to fit the post-size limit, as the attachment system does not allow text files. Why not?!)

9-10-13 4:39:04.929 pm com.apple.backupd[690]: Starting automatic backup
9-10-13 4:39:06.000 pm kernel[0]: nspace-handler-set-snapshot-time: 1381351148
9-10-13 4:39:06.310 pm com.apple.backupd[690]: Network destination already mounted at: /Volumes/MyBook2TB_Office
9-10-13 4:39:08.331 pm com.apple.backupd[690]: Disk image already attached: /Volumes/MyBook2TB_Office/Qweeg.sparsebundle, DIHLDiskImageAttach returned: 35
9-10-13 4:39:09.592 pm com.apple.backupd[690]: Disk image /Volumes/MyBook2TB_Office/Qweeg.sparsebundle mounted at: /Volumes/Time Machine Backups
9-10-13 4:39:09.595 pm com.apple.backupd[690]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
9-10-13 4:39:09.598 pm com.sophos.intercheck[105]: Info: Exclusion: /.MobileBackups/ at 16:39 on 09 October 2013
9-10-13 4:39:09.598 pm com.sophos.intercheck[105]: Info: Exclusion: /Applications/Jitsi.app/ at 16:39 on 09 October 2013
9-10-13 4:39:09.598 pm com.sophos.intercheck[105]: Info: Exclusion: /Library/Internet Plug-Ins/JavaAppletPlugin.plugin/ at 16:39 on 09 October 2013
9-10-13 4:39:09.598 pm com.sophos.intercheck[105]: Info: Exclusion: /System/Library/Java/ at 16:39 on 09 October 2013
9-10-13 4:39:09.599 pm com.sophos.intercheck[105]: Info: Exclusion: /Users/chrisc-nobackup/EyeTV Archive/Live TV Buffer.eyetv/ at 16:39 on 09 October 2013
9-10-13 4:39:09.599 pm com.sophos.intercheck[105]: Info: Exclusion: /Volumes/MobileBackups/ at 16:39 on 09 October 2013
9-10-13 4:39:09.599 pm com.sophos.intercheck[105]: Info: Exclusion: /Volumes/Time Machine Backups/ at 16:39 on 09 October 2013
9-10-13 4:39:09.599 pm com.sophos.intercheck[105]: Info: Exclusion: /Volumes/MyBook2TB_Office/ at 16:39 on 09 October 2013
9-10-13 4:41:03.188 pm com.apple.backupd[690]: Waiting for Spotlight to finish indexing /Volumes/Time Machine Backups/Backups.backupdb
9-10-13 4:45:57.000 pm kernel[0]: sav: [EWOULDBLOCK][vnode:0xffffff803cacd8b8][original:0xffffff803cacd8b8][callback: 0 count:160113 ] onaccessctl_check:1825 result:0 disconnected:0
9-10-13 4:45:57.000 pm kernel[0]: sav: current scan list:
9-10-13 4:45:57.000 pm kernel[0]: sav: (pid 80 [mtmd], vnode 0xffffff803acbb9b0 [/Users/chrisc/Music/iTunes/Mobile Applications/Downloads/Kik Messenger.tmp/download.app], [context 0xffffff80347add70] [result 0] [setup 0] [disconnected 0] [vfsbusy 0]) - 1 waiter(s)
9-10-13 4:45:57.000 pm kernel[0]: sav: (pid 81 [mds], vnode 0xffffff803cacd8b8 [], [context 0xffffff803437b150] [result 0] [setup 0] [disconnected 0] [vfsbusy 0]) - 1 waiter(s)
9-10-13 4:45:57.000 pm kernel[0]: sav: available kctl entries: 8
9-10-13 4:49:06.706 pm com.sophos.intercheck[105]: Corrupt file: /Users/chrisc/Music/iTunes/Mobile Applications/Downloads/Kik Messenger.tmp/download.app
9-10-13 4:49:06.000 pm kernel[0]: sav: [EWOULDBLOCK][vnode:0xffffff803acbb9b0][original:0xffffff803acbb9b0][callback: 0 count:278 ] onaccessctl_check:1825 result:0 disconnected:0
9-10-13 4:49:06.000 pm kernel[0]: sav: current scan list:
9-10-13 4:49:06.000 pm kernel[0]: sav: (pid 81 [mds], vnode 0xffffff803dd38b20 [/7EE7B36D0E673FD7-B6B8FB6DFC21A785.itc], [context 0xffffff802f900470] [result 0] [setup 0] [disconnected 0] [vfsbusy 1]) - 1 waiter(s)
9-10-13 4:49:06.000 pm kernel[0]: sav: (pid 80 [mtmd], vnode 0xffffff803acbb9b0 [/Users/chrisc/Music/iTunes/Mobile Applications/Downloads/Kik Messenger.tmp/download.app], [context 0xffffff80347add70] [result 0] [setup 0] [disconnected 0] [vfsbusy 0]) - 1 waiter(s)
9-10-13 4:49:06.000 pm kernel[0]: sav: (pid 80 [mtmd], vnode 0 [/Users/chrisc/Music/iTunes/Mobile Applications/Downloads/Kik Messenger.tmp/download.app], [context 0] [result 0] [setup 0] [disconnected 0] [vfsbusy 0]) - 0 waiter(s)
9-10-13 4:49:06.000 pm kernel[0]: sav: available kctl entries: 7
9-10-13 4:49:06.000 pm kernel[0]: nspace-handler-unblock: did not find token 11001
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:3 kctl_entry:0xffffff8033b1b000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: SAV_KCTL_REQ_COMPLETE, intercheck_done()
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:0 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: not SAV_KCTL_REQ_COMPLETE, return ENOMEM
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: NULL target or context; request:3 kctl_entry:0xffffff8034a8c000
9-10-13 4:49:06.000 pm kernel[0]: sav: onaccess_send: SAV_KCTL_REQ_COMPLETE, intercheck_done()
9-10-13 4:49:06.771 pm com.sophos.intercheck[105]: Issue: Could not scan
9-10-13 4:49:06.772 pm com.sophos.intercheck[105]: An unexpected error occurred

   Has anyone else seen this sort of thing? I have now experienced it on 2 MacBook Pro 17" models (thay aren't the same)

Regards,

Chris

:1013773


This thread was automatically locked due to age.
Parents
  • 0

    Hi Sophos,

       Some more information about this problem: it appears to be agravated and possibly caused by enabling the "Scan inside archives and compressed files" option if the archive is a very big file.

       Separately, I've noticed that copying a 16GB .tar.gz archive from one computer to another using Finder, both using OS X 10.9 and with this option enabled on both computers makes diff decide that the binary files differ. When I repeated the operation without On-Access scanning turned on on either computer, diff decided the copy was identical. It also took much longer to decide. That's rather scary.

       Sophos Technical support, you might want to try testing the above. I did not try various combinations of enabled and disabled on the local and remote computers, nor did I try combinations including the scan inside archive flag enabled and disabled.

       I've turned off "Scan inside archives and compressed files".. but it's rather a shame for obvious reasons.

    Regards,

    Chris

    :1014645
Reply
  • 0

    Hi Sophos,

       Some more information about this problem: it appears to be agravated and possibly caused by enabling the "Scan inside archives and compressed files" option if the archive is a very big file.

       Separately, I've noticed that copying a 16GB .tar.gz archive from one computer to another using Finder, both using OS X 10.9 and with this option enabled on both computers makes diff decide that the binary files differ. When I repeated the operation without On-Access scanning turned on on either computer, diff decided the copy was identical. It also took much longer to decide. That's rather scary.

       Sophos Technical support, you might want to try testing the above. I did not try various combinations of enabled and disabled on the local and remote computers, nor did I try combinations including the scan inside archive flag enabled and disabled.

       I've turned off "Scan inside archives and compressed files".. but it's rather a shame for obvious reasons.

    Regards,

    Chris

    :1014645
Children
No Data