locked
Debugging RMSBulk with dbgview.exe RRS feed

  • Question

  • Hello,

    I am currently trying to figure out why RMSBulk doesn't work on 2/3 of my web servers.  I have attached dbgviewer and captured the results, but cannot make anysense of "what" is really going on or what is confiured incorrectly / installed / patched etc....

    Servers: Win 2008 R2

    Windows service shelling out to RMSBulk to DRM XPS documents.

    thanks,

    stephen

    TRACE:

    [\\TK5HRITW7502]
    00000001 0.00000000 [2680] [IRMProtectorWrapper]:HrNativeIRMInitialize Entered
    00000002 0.00014052 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::Initialize Entered
    00000003 0.00022349 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::PopulateIrmProtectors Entered
    00000004 0.00260396 [2680] [IRMProtectorWrapper]:CoCreateInstance for {2E4402B2-F2DA-4BC8-BB2C-41BECF0BDDDB}, hr = 0x0
    00000005 0.00276152 [2680] [IRMProtectorWrapper]:Initialize Protector {2E4402B2-F2DA-4BC8-BB2C-41BECF0BDDDB}, hr = 0x0
    00000006 0.00284198 [2680] [IRMProtectorWrapper]:Protector {2E4402B2-F2DA-4BC8-BB2C-41BECF0BDDDB},has extenseions doc,dot,xls,xlt,xla,ppt,pot,pps
    00000007 0.00451426 [2680] [IRMProtectorWrapper]:CoCreateInstance for {81273702-956F-4CBD-9B16-43790558EE29}, hr = 0x0
    00000008 0.00459807 [2680] [IRMProtectorWrapper]:Initialize Protector {81273702-956F-4CBD-9B16-43790558EE29}, hr = 0x0
    00000009 0.00467797 [2680] [IRMProtectorWrapper]:Protector {81273702-956F-4CBD-9B16-43790558EE29},has extenseions xps,docx,docm,dotx,dotm,xlsx,xlsm,xlsb,xltx,xltm,xlam,pptx,pptm,potx,potm,thmx,ppsx,ppsm
    00000010 0.00476010 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::PopulateIrmProtectors Exited with hr = 0x0
    00000011 0.00484196 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::Initialize Exited with hr = 0x0
    00000012 0.00491850 [2680] [IRMProtectorWrapper]:HrNativeIRMInitialize Exited with hr = 0x0
    00000013 0.01279883 [2680] [IRMProtectorWrapper]:HrNativeIRMProtect Entered
    00000014 0.01287147 [2680] [IRMProtectorWrapper]:Operating on File: c:\workingarea\test5drm.xps
    00000015 0.01362268 [2680] [IRMProtectorWrapper]:CIrmClient::HrInit Entered
    00000016 0.01375119 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitSecrep Entered
    00000017 0.01453648 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitSecrep Exited with hr = 0x0
    00000018 0.01460213 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitClient Entered
    00000019 0.01470410 [2680] [msdrm]:+DRMCreateClientSession - uCallbackVersion = 0,wszGroupIDProviderType = WindowsAuthProvider,wszGroupID = foo@foo.com
    00000020 0.01513852 [2680] [msdrm]:-DRMCreateClientSession HR=0
    00000021 0.01520668 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitClient Exited with hr = 0x0
    00000022 0.01528602 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitPublishingUser Entered
    00000023 0.01535139 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Entered
    00000024 0.01542906 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_GROUPIDENTITY_NAME,uIndex=0
    00000025 0.01828473 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000026 0.01835513 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_GROUPIDENTITY_NAME,uIndex=0
    00000027 0.01842217 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000028 0.01849006 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Exited with hr = 0x0
    00000029 0.01855739 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitPublishingUser Exited with hr = 0x0
    00000030 0.01864595 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitClient Entered
    00000031 0.01871132 [2680] [msdrm]:+DRMCloseSession
    00000032 0.01883256 [2680] [msdrm]:-DRMCloseSession HR=0
    00000033 0.01890911 [2680] [msdrm]:+DRMCreateClientSession - uCallbackVersion = 0,wszGroupIDProviderType = WindowsAuthProvider,wszGroupID = someID@someID.com
    00000034 0.01921501 [2680] [msdrm]:-DRMCreateClientSession HR=0
    00000035 0.01930050 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitClient Exited with hr = 0x0
    00000036 0.01936531 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitMachine Entered
    00000037 0.01943012 [2680] [msdrm]:+DRMIsActivated - uFlags = DRM_ACTIVATE_MACHINE
    00000038 0.02714004 [2680] [msdrm]:-DRMIsActivated HR=0
    00000039 0.02721044 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Entered
    00000040 0.02727525 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_MACHINE,uIndex=0
    00000041 0.02881344 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000042 0.02891401 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_MACHINE,uIndex=0
    00000043 0.03055752 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000044 0.03062261 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Exited with hr = 0x0
    00000045 0.03068658 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitMachine Exited with hr = 0x0
    00000046 0.03074860 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitGIC Entered
    00000047 0.03085336 [2680] [msdrm]:+DRMIsActivated - uFlags = DRM_ACTIVATE_GROUPIDENTITY
    00000048 0.03666360 [2680] [msdrm]:-DRMIsActivated HR=0
    00000049 0.03672841 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitGIC Exited with hr = 0x0
    00000050 0.03679015 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Entered
    00000051 0.03685385 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_SPECIFIED_GROUPIDENTITY,uIndex=0
    00000052 0.03927622 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000053 0.03937120 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_SPECIFIED_GROUPIDENTITY,uIndex=0
    00000054 0.04038391 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000055 0.04044788 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Exited with hr = 0x0
    00000056 0.04051018 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitEnvironment Entered
    00000057 0.04056996 [2680] [msdrm]:+DRMInitEnvironment
    00000058 0.35242775 [2680] [msdrm]:SPCreateSecurityProcessor took 328 milliseconds
    00000059 0.35249284 [2680] [msdrm]:Environment Handle Creation took 0 milliseconds
    00000060 0.35254648 [2680] [msdrm]:-DRMInitEnvironment HR=0x0
    00000061 0.35260990 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitEnvironment Exited with hr = 0x0
    00000062 0.35266662 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitCLCCert Entered
    00000063 0.35271996 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Entered
    00000064 0.35277557 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_SPECIFIED_CLIENTLICENSOR,uIndex=0
    00000065 0.35476547 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000066 0.35485852 [2680] [msdrm]:+DRMEnumerateLicense uFlags = DRM_EL_SPECIFIED_CLIENTLICENSOR,uIndex=0
    00000067 0.35572258 [2680] [msdrm]:-DRMEnumerateLicense HR=0
    00000068 0.35577735 [2680] [IRMProtectorWrapper]:CIrmClient::HrGetCert Exited with hr = 0x0
    00000069 0.35583210 [2680] [IRMProtectorWrapper]:CIrmClient::HrInitCLCCert Exited with hr = 0x0
    00000070 0.35588574 [2680] [IRMProtectorWrapper]:CIrmClient::HrInit Exited with hr = 0x0
    00000071 0.35959038 [2680] [msdrm]:+DRMCreateIssuanceLicense
    00000072 0.36061817 [2680] [msdrm]:-DRMCreateIssuanceLicense HR=0
    00000073 0.36071345 [2680] +DRMSetMetaData (Content ID={C3072C30-CE59-4298-AD88-EC3585DCCFFE}, Content ID Type=MS-GUID, SKU ID=(null), SKU ID Type=(null), Content Type=RMS Bulk Protected Document, Content Name=(null)
    00000074 0.36077797 [2680] -DRMSetMetaData HR=0
    00000075 0.36084473 [2680] [msdrm]:+DRMGetSignedIssuanceLicense
    00000076 0.36107689 [2680] [msdrm]:DRMGetSignedIssuanceLicense Args: SymKeyType=AES,  URL=(null)
    00000077 0.36118782 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 0
    00000078 0.36141941 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000079 0.36147666 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 0
    00000080 0.36172614 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000081 0.36178228 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 1
    00000082 0.36203036 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000083 0.36238292 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 1
    00000084 0.36264917 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000085 0.36270308 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 2
    00000086 0.36303189 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000087 0.36310172 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 2
    00000088 0.36343417 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000089 0.36348614 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 3
    00000090 0.36377975 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000091 0.36383340 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 3
    00000092 0.36412337 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000093 0.36417535 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 4
    00000094 0.36447173 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000095 0.36452454 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 4
    00000096 0.36483380 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=0
    00000097 0.36488548 [2680] [msdrm]:+DRMDeconstructCertificateChain iWhich = 5
    00000098 0.36520228 [2680] [msdrm]:-DRMDeconstructCertificateChain HR=80070057
    00000099 0.36886281 [2680] [msdrm]:+DRMConstructCertificateChain
    00000100 0.36951262 [2680] [msdrm]:-DRMConstructCertificateChain HR=0
    00000101 0.36958244 [2680] [msdrm]:+DRMConstructCertificateChain
    00000102 0.37033367 [2680] [msdrm]:-DRMConstructCertificateChain HR=0
    00000103 0.37041858 [2680] [msdrm]:+DRMConstructCertificateChain
    00000104 0.37099436 [2680] [msdrm]:-DRMConstructCertificateChain HR=0
    00000105 0.37106195 [2680] [msdrm]:+DRMConstructCertificateChain
    00000106 0.37179697 [2680] [msdrm]:-DRMConstructCertificateChain HR=0
    00000107 0.37187046 [2680] [msdrm]:+DRMCreateBoundLicense
    00000108 0.37194055 [2680] Created the enabling principal
    00000109 0.39961308 [2680] [msdrm]:-DRMCreateBoundLicense HR=0x8004cf18
    00000110 0.40116104 [2680] [msdrm]:-DRMGetSignedIssuanceLicense HR=8004cf58
    00000111 0.40122727 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInitSignedIL FAILED at Line 658 with hr = 0x8004cf58
    00000112 0.40128508 [2680] [msdrm]:+DRMClosePubHandle
    00000113 0.40134013 [2680] [msdrm]:+DRMCloseSession
    00000114 0.40142810 [2680] [msdrm]:-DRMCloseSession HR=0
    00000115 0.40148371 [2680] [msdrm]:-DRMClosePubHandle HR=0
    00000116 0.40154320 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInitSignedIL FAILED at Line 693 with hr = 0x8004cf58
    00000117 0.40160245 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInit FAILED at Line 116 with hr = 0x8004cf58
    00000118 0.40166250 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInit FAILED at Line 137 with hr = 0x8004cf58
    00000119 0.40172172 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::IRMProtect FAILED at Line 301 with hr = 0x8004cf58
    00000120 0.40181392 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::IRMProtect FAILED at Line 351 with hr = 0x8004cf58
    00000121 0.40187314 [2680] [IRMProtectorWrapper]:CIrmProtectorWrapper::IRMProtect Exited with hr = 0x8004cf58
    00000122 0.40193096 [2680] [IRMProtectorWrapper]:HrNativeIRMProtect Exited with hr = 0x8004cf58
    00000123 0.40714505 [2680] [IRMProtectorWrapper]:HrNativeIRMCleanup Entered
    00000124 0.40721628 [2680] [msdrm]:+DRMCloseHandle
    00000125 0.40728948 [2680] [msdrm]:-DRMCloseHandle HR=0x0
    00000126 0.40735233 [2680] [msdrm]:+DRMCloseEnvironmentHandle
    00000127 0.40879190 [2680] [msdrm]:-DRMCloseEnvironmentHandle HR=0x0
    00000128 0.40885448 [2680] [msdrm]:+DRMCloseSession
    00000129 0.40902880 [2680] [msdrm]:-DRMCloseSession HR=0
    00000130 0.40911597 [2680] [IRMProtectorWrapper]:HrNativeIRMCleanup Exited with hr = 0x0
    00000131 14.43167114 [2332] 2332: 2012-08-01 15:43:51.547 [CBS]                       IsCacheStillGood: True.

    Thursday, August 2, 2012 4:50 PM

Answers

  • 00000111 0.40122727 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInitSignedIL FAILED at Line 658 with hr = 0x8004cf58

    indicates trouble with CLC.

    From http://msdn.microsoft.com/en-us/library/windows/desktop/bb204613(v=vs.85).aspx
    E_DRM_INVALID_CLIENT_LICENSOR_CERTIFICATE (0x8004CF58)

    How are you trying to run the bulk protection tool? Is from within a IIS/ASP.NET application or are you trying to run interactively or do you have a standard scheduled job? Under which credentials do you run the bulk protection tool? Is the user profile loaded?

    Martin

    Friday, August 3, 2012 2:01 PM

All replies

  • Hi Stephen,

    what is the purpose for you to run rmsbulk on a web server? And in what user context is the rmsbulk running. What is your Windows version on the RMS server and web server? 

    regards,

    Lutz

    Friday, August 3, 2012 7:00 AM
  • 00000111 0.40122727 [2680] [IRMProtectorWrapper]:CIrmDocument::HrInitSignedIL FAILED at Line 658 with hr = 0x8004cf58

    indicates trouble with CLC.

    From http://msdn.microsoft.com/en-us/library/windows/desktop/bb204613(v=vs.85).aspx
    E_DRM_INVALID_CLIENT_LICENSOR_CERTIFICATE (0x8004CF58)

    How are you trying to run the bulk protection tool? Is from within a IIS/ASP.NET application or are you trying to run interactively or do you have a standard scheduled job? Under which credentials do you run the bulk protection tool? Is the user profile loaded?

    Martin

    Friday, August 3, 2012 2:01 PM
  • In addition to checking what Martin is suggesting , can you verify if you have multiple CLCs in your DRM folder ? I wonder if it is picking up the wrong CLC.
    Saturday, August 4, 2012 4:00 AM