ConfigMgr 2012 Log: OfflineServicingMgr.log

I like browsing through log files, especially new log files I haven’t seen before.  They’re treasure troves of information that everyday users of the ConfigMgr GUI should discover and get acquainted with.  With ConfigMgr 2012 we have an influx of new information relating to the new activities we can perform.

Below we have a cycle of events from the OfflineServicingMgr.log, which gives us an insight as to what happens when we perform Image Servicing using the ConfigMgr 2012 console.  The Image Servicing feature lows us to more easily apply Software Updates to our captured reference image without having to resort to command line tools or third party utilities.

If you have a nervous disposition to log files, look away now…

OfflineServicingMgr.log

23/03/2012 09:56:16 SMS_EXECUTIVE started SMS_OFFLINE_SERVICING_MANAGER as thread ID 5832 (0x16C8).
23/03/2012 09:56:16 Checking if there are schedule(s) which need to be run at this time.
23/03/2012 09:56:16 Schedule with ID 16777217 (Schedule Name = ) is marked for RunNow by the administrator
23/03/2012 09:56:16 The Schedule with ID 16777217 will be run now. It's run time is at Fri Mar 23 09:56:16 2012 GMT Standard Time
23/03/2012 09:56:16 Schedule with ID 16777217 () is active
23/03/2012 09:56:16 Schedule processing thread started. ThreadID = 0xD08 (3336) 23/03/2012 09:56:16 1 Schedule(s) are marked for RunNow by the administrator
23/03/2012 09:56:16 1 Schedule(s) are scheduled to be run at this time 23/03/2012 09:56:16 Processing started for Schedule with ID 16777217 (Schedule Name = )
23/03/2012 09:56:16 STATMSG: ID=7900 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 09:56:16.443 2012 ISTR0="16777217" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 09:56:16 Initialization of schedule processing succeeded
23/03/2012 09:56:16 There is an image associated with this schedule.
23/03/2012 09:56:16 Total number of individual updates to be installed is 5.
23/03/2012 09:56:16 STATMSG: ID=7903 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 09:56:16.567 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 09:56:16 Copy image MS10000A (size 0 MB):'
23/03/2012 09:56:16 copying file '\\server\sources\Operating System Images\win7entsp1x64_v1.wim' to 'F:\ConfigMgr_OfflineImageServicing\MS10000A\win7entsp1x64_v1.wim' ...
23/03/2012 09:57:32 Copying(25% complete)...
23/03/2012 09:58:40 Copying(50% complete)...
23/03/2012 09:59:50 Copying(75% complete)...
23/03/2012 10:00:59 Copying(100% complete)...
23/03/2012 10:01:00 STATMSG: ID=7905 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:01:00.042 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:01:00 [Schedule ID 16777217] Started processing image package with ID MS10000A
23/03/2012 10:01:00 STATMSG: ID=7906 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:01:00.043 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:01:00 Image package file with ID MS10000A contains 1 image(s)
23/03/2012 10:01:00 Processing image at index 1 23/03/2012 10:01:00 Mounting image at index 1. Image file='F:\ConfigMgr_OfflineImageServicing\MS10000A\win7entsp1x64_v1.wim', MountDirectory='F:\ConfigMgr_OfflineImageServicing\MS10000A\ImageMountDir', ImageFileType='WIM', Mode='ReadWrite'
23/03/2012 10:01:36 Image OS information : MajorVersionMS = 6, MinorVersionMS = 1, MajorVersionLS = 7601, MinorVersionLS = 17651
23/03/2012 10:01:36 Checking if update (1 of 5) with ID 16781310 needs to be applied on the image. 1 content binarie(s) are associated with the update.
23/03/2012 10:01:46 Applicability State = APPLICABLE, Update Binary = \\server\sources\Software Updates\Windows 7 Updates\d27e6166-5484-4174-ad94-b5bd0405d3d9\windows6.1-kb2645640-x64.cab.
23/03/2012 10:01:46 Applying update with ID 16781310 on image at index 1.
23/03/2012 10:01:53 STATMSG: ID=7908 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:01:53.163 2012 ISTR0="16781310" ISTR1="MS10000A" ISTR2="1" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:01:53 This update binary was succesfully updated on the mounted image. 
23/03/2012 10:01:53 Checking if update (2 of 5) with ID 16781400 needs to be applied on the image. 1 content binarie(s) are associated with the update.
23/03/2012 10:02:00 Applicability State = APPLICABLE, Update Binary = \\server\sources\Software Updates\Windows 7 Updates\cc887950-d1b5-45a8-aa5d-0bd593defcf6\windows6.1-kb2621440-x64.cab.
23/03/2012 10:02:00 Applying update with ID 16781400 on image at index 1.
23/03/2012 10:02:09 STATMSG: ID=7908 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:02:09.661 2012 ISTR0="16781400" ISTR1="MS10000A" ISTR2="1" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:02:09 This update binary was succesfully updated on the mounted image.
23/03/2012 10:02:09 Checking if update (3 of 5) with ID 16781406 needs to be applied on the image. 1 content binarie(s) are associated with the update.
23/03/2012 10:02:18 Applicability State = APPLICABLE, Update Binary = \\server\sources\Software Updates\Windows 7 Updates\be82d4ec-e2aa-4e31-b0cb-60a71c41a60f\windows6.1-kb2641653-x64.cab.
23/03/2012 10:02:18 Applying update with ID 16781406 on image at index 1.
23/03/2012 10:02:29 STATMSG: ID=7908 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:02:29.005 2012 ISTR0="16781406" ISTR1="MS10000A" ISTR2="1" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:02:29 This update binary was succesfully updated on the mounted image.
23/03/2012 10:02:29 Checking if update (4 of 5) with ID 16781420 needs to be applied on the image. 1 content binarie(s) are associated with the update.
23/03/2012 10:02:39 Applicability State = APPLICABLE, Update Binary = \\server\sources\Software Updates\Windows 7 Updates\9d33f980-59ec-4bee-b83e-6e78c4e21fce\windows6.1-kb2665364-x64.cab.
23/03/2012 10:02:39 Applying update with ID 16781420 on image at index 1.
23/03/2012 10:02:51 STATMSG: ID=7908 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:02:51.428 2012 ISTR0="16781420" ISTR1="MS10000A" ISTR2="1" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:02:51 This update binary was succesfully updated on the mounted image.
23/03/2012 10:02:51 Checking if update (5 of 5) with ID 16781430 needs to be applied on the image. 1 content binarie(s) are associated with the update.
23/03/2012 10:03:02 Applicability State = APPLICABLE, Update Binary = \\server\sources\Software Updates\Windows 7 Updates\5b8222b9-80e8-465f-a827-ef18dcda0a7d\windows6.1-kb2667402-x64.cab.
23/03/2012 10:03:02 Applying update with ID 16781430 on image at index 1.
23/03/2012 10:03:16 STATMSG: ID=7908 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:03:16.952 2012 ISTR0="16781430" ISTR1="MS10000A" ISTR2="1" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:03:16 This update binary was succesfully updated on the mounted image.
23/03/2012 10:03:16 Total number of updates that are succesfully applied on the mounted image is 5
23/03/2012 10:03:16 UnMounting Image (Commit Changes = 1) ...
23/03/2012 10:04:28 STATMSG: ID=7907 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:04:28.799 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:04:28 Completed processing image package MS10000A. Status = Success
23/03/2012 10:04:28 STATMSG: ID=7904 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:04:28.815 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:04:28 Create backup copy for image MS10000A 23/03/2012 10:04:28 copying image file '\\server\sources\Operating System Images\win7entsp1x64_v1.wim' to '\\server\sources\Operating System Images\win7entsp1x64_v1.wim.bak' ...
23/03/2012 10:04:28 Copy image MS10000A (size 0 MB):' 23/03/2012 10:04:28 copying file 'F:\ConfigMgr_OfflineImageServicing\MS10000A\win7entsp1x64_v1.wim' to '\\server\sources\Operating System Images\win7entsp1x64_v1.wim' ...
23/03/2012 10:05:46 Copying(25% complete)...
23/03/2012 10:07:00 Copying(50% complete)...
23/03/2012 10:08:06 Copying(75% complete)...
23/03/2012 10:09:19 Copying(100% complete)...
23/03/2012 10:09:19 A backup copy of the original image is created:
23/03/2012 10:09:19 original file '\\server\sources\Operating System Images\win7entsp1x64_v1.wim' is backed up at '\\server\sources\Operating System Images\win7entsp1x64_v1.wim.bak'
23/03/2012 10:09:19 STATMSG: ID=7905 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:09:19.467 2012 ISTR0="MS10000A" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:09:19 Updated history for image package MS10000A in the database
23/03/2012 10:09:19 Schedule processing succeeded
23/03/2012 10:09:19 Processing completed for Schedule with ID 16777217 (Schedule Name = )
23/03/2012 10:09:19 STATMSG: ID=7901 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFLINE_SERVICING_MANAGER" SYS=server.contoso.local SITE=MS1 PID=2148 TID=3336 GMTDATE=Fri Mar 23 10:09:19.496 2012 ISTR0="16777217" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0
23/03/2012 10:09:19 Schedule processing thread stopped 23/03/2012 10:09:19 Checking if there are schedule(s) which need to be run at this time.
23/03/2012 10:09:19 This Schedule with ID 16777217 does not have a next run time
23/03/2012 10:09:19 No more schedules are found to be run at this time or in the future. Will sleep till a new schedule is created.
23/03/2012 10:09:19 No schedule exists which needs to be run anytime in future.
23/03/2012 10:09:19 Offline Servicing Manager thread is exiting.

From what I can see from this log, ConfigMgr makes a copy of our original .wim file into a “ConfigMgr_OfflineImageServicing” folder and mounts this copied image.  It then determines applicability of the Software Updates we have asked it to apply to the image and applies them as required.  After applying the Software Updates, the changes are committed back to the copied .wim file.  It is a little unclear here, but it looks like our original .wim filename is renamed with a .bak extension and the newly serviced .wim file is then copied over to the original source location.

We should note that disk space requirements can get pretty heavy for this process to complete – you should probably budget on having disk freespace that is at least quadruple the size of your reference image available in order for this process to complete.

What I don’t seem to see once this process has completed is any activity from the Distribution Manager log (distmgr.log,)  When we examine the properties of the Operating System Image from within the ConfigMgr console after this process has completed I find that the Image properties have not been automatically reloaded and the OS Image source version hasn’t been updated.  Now, this may just be because at the time I hadn’t actually assigned any distribution points to the image, however if this is not the case then the servicing utility is only doing half a job for us.

Ideally, given that we can schedule image servicing to happen out of hours, we should also at least be given the option to have the image changes distributed throughout the infrastructure so that deployments the next day would use the updated image.  As it stands, it seems we have to manually reload the image properties and then update our distribution points.

Andy

Advertisements

About madluka

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: