search

jabbera / vsts-authenticode

A task to authenticode sign dlls
MIT License
7 stars 4 forks source link

Repeatedly issues with signing #20

Closed dnperfors closed 4 years ago

dnperfors commented 5 years ago

Hi,

Since a couple of weeks we are using this plugin in our builds in order to be able to use the Secure file storage of TFS. Most of the time this works like a charm, but sometimes we notice that we get the following message:

2019-03-18T07:48:27.7364419Z [command]C:\BuildAgent_work_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent_work_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 <...several assembly files...> 2019-03-18T07:48:27.9965373Z SignTool Error: An error occurred while attempting to load the signing 2019-03-18T07:48:27.9966085Z 2019-03-18T07:48:27.9966955Z certificate from: C:\BuildAgent_work_temp\CodeSignCertificate-2022-02-20.pfx 2019-03-18T07:48:27.9967702Z 2019-03-18T07:48:28.0134499Z Error attempting to sign. Attempt number: 0. Exception text: Error: C:\BuildAgent_work_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1 2019-03-18T07:48:28.0140299Z Sleeping for 15 second(s)

How could we debug these kind of issue and get the root cause of it?

Regards, David

jabbera commented 5 years ago

Hi,

Can you make sure system.debug is set to true and post the log of the task please.

Do all the retries fail with the same pattern? There is a loop of retries meant to deal with timestamp server issues, and I’m surprised any transient error isn’t being handled by this logic.

dnperfors commented 5 years ago

I enable debug logging for the build, but it could take some time before I have the information. It doesn't run consistently into this issue. and the log added...

it does fail for 5 retries, because the build breaks, I also tried other timestamp servers, but looking at the error message I don't really think it is caused by that, but rather some weird issue with getting the certificate itself?

Here is the slightly redacted debug log of a failing authenticode task:

2019-03-18T13:16:38.9985918Z ##[section]Starting: Authenticode Sign
2019-03-18T13:16:39.0042448Z ==============================================================================
2019-03-18T13:16:39.0043126Z Task         : Authenticode Sign
2019-03-18T13:16:39.0043661Z Description  : Authenticode sign executable code.
2019-03-18T13:16:39.0044151Z Version      : 3.0.0
2019-03-18T13:16:39.0044617Z Author       : Michael Barry
2019-03-18T13:16:39.0045053Z Help         : 
2019-03-18T13:16:39.0045575Z ==============================================================================
2019-03-18T13:16:39.6393198Z ##[debug]agent.TempDirectory=C:\BuildAgent\_work\_temp
2019-03-18T13:16:39.6458873Z ##[debug]loading inputs and endpoints
2019-03-18T13:16:39.6471466Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2019-03-18T13:16:39.6496697Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2019-03-18T13:16:39.6503553Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2019-03-18T13:16:39.6508724Z ##[debug]loading INPUT_CERTIFICATELOCATION
2019-03-18T13:16:39.6512363Z ##[debug]loading INPUT_CERTIFICATESELECTIONMETHOD
2019-03-18T13:16:39.6516471Z ##[debug]loading INPUT_FILEALGO
2019-03-18T13:16:39.6520724Z ##[debug]loading INPUT_FILEPATH
2019-03-18T13:16:39.6524107Z ##[debug]loading INPUT_PFXFILE
2019-03-18T13:16:39.6528718Z ##[debug]loading INPUT_PFXPASSWORD
2019-03-18T13:16:39.6531948Z ##[debug]loading INPUT_PFXSECUREFILE
2019-03-18T13:16:39.6536263Z ##[debug]loading INPUT_RETRYCOUNT
2019-03-18T13:16:39.6539820Z ##[debug]loading INPUT_SIGNROOTPATH
2019-03-18T13:16:39.6543533Z ##[debug]loading INPUT_TIMESTAMPALGO
2019-03-18T13:16:39.6547704Z ##[debug]loading INPUT_TIMESTAMPSERVER
2019-03-18T13:16:39.6550416Z ##[debug]loading INPUT_TIMESTAMPSERVERDELAY
2019-03-18T13:16:39.6559937Z ##[debug]loading SECRET_CODESIGNPASSWORD
2019-03-18T13:16:39.6565546Z ##[debug]loading SECRET_SONARQUBE_ENDPOINT
2019-03-18T13:16:39.6570265Z ##[debug]loading SECRET_SQLPASSWORD
2019-03-18T13:16:39.6574485Z ##[debug]loading SECUREFILE_TICKET_5c45de5a-1cfd-4206-b09b-c4565372bfc4
2019-03-18T13:16:39.6584100Z ##[debug]loaded 19
2019-03-18T13:16:39.6616596Z ##[debug]Agent.ProxyUrl=undefined
2019-03-18T13:16:39.6618444Z ##[debug]Agent.CAInfo=undefined
2019-03-18T13:16:39.6619209Z ##[debug]Agent.ClientCert=undefined
2019-03-18T13:16:40.3058108Z ##[debug]signToolLocation=null
2019-03-18T13:16:40.3060403Z ##[debug]Using tool location: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe
2019-03-18T13:16:40.3063329Z ##[debug]check path : C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe
2019-03-18T13:16:40.3207859Z ##[debug]retryCount=5
2019-03-18T13:16:40.3221000Z ##[debug]timestampServerDelay=15
2019-03-18T13:16:40.3231034Z ##[debug]which 'C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe'
2019-03-18T13:16:40.3249298Z ##[debug]found: 'C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe'
2019-03-18T13:16:40.3250630Z ##[debug]which 'C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe'
2019-03-18T13:16:40.3251982Z ##[debug]found: 'C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe'
2019-03-18T13:16:40.3258642Z ##[debug]timestampServer=http://timestamp.digicert.com
2019-03-18T13:16:40.3262974Z ##[debug]timestampAlgo=sha256
2019-03-18T13:16:40.3282499Z ##[debug]certificateLocation=secureFile
2019-03-18T13:16:40.3288666Z ##[debug]pfxSecureFile=5c45de5a-1cfd-4206-b09b-c4565372bfc4
2019-03-18T13:16:40.3291144Z ##[debug]System.TeamFoundationCollectionUri=https://<redacted>/tfs/DefaultCollection/
2019-03-18T13:16:40.3299764Z ##[debug]SYSTEMVSSCONNECTION auth param ACCESSTOKEN = ***
2019-03-18T13:16:40.3370612Z ##[debug]secure file name for id 5c45de5a-1cfd-4206-b09b-c4565372bfc4 = CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:40.3371780Z ##[debug]Agent.TempDirectory=C:\BuildAgent\_work\_temp
2019-03-18T13:16:40.3377230Z ##[debug]Absolute path for pathSegments: C:\BuildAgent\_work\_temp,CodeSignCertificate-2022-02-20.pfx = C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:40.3378727Z ##[debug]Downloading secure file contents to: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:40.3405397Z ##[debug]SYSTEM.TEAMPROJECT=Platform
2019-03-18T13:16:40.3413863Z ##[debug]secure file ticket for id 5c45de5a-1cfd-4206-b09b-c4565372bfc4 = ***
2019-03-18T13:16:40.4923975Z ##[debug]Downloaded secure file contents to: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:40.4925299Z ##[debug]check path : C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:40.4936126Z ##[debug]pfxPassword=***
2019-03-18T13:16:40.4940644Z ##[debug]additionalArguments=null
2019-03-18T13:16:40.4948645Z ##[debug]fileAlgo=sha256
2019-03-18T13:16:40.4952581Z ##[debug]filePath=bin/**/*.dll
2019-03-18T13:16:40.4958487Z ##[debug]signRootPath=C:\BuildAgent\_work\1\a\
2019-03-18T13:16:40.4971812Z ##[debug]defaultRoot: 'C:\BuildAgent\_work\1\a\'
2019-03-18T13:16:40.4973577Z ##[debug]findOptions.followSpecifiedSymbolicLink: 'true'
2019-03-18T13:16:40.4974394Z ##[debug]findOptions.followSymbolicLinks: 'true'
2019-03-18T13:16:40.4977834Z ##[debug]matchOptions.debug: 'false'
2019-03-18T13:16:40.4978773Z ##[debug]matchOptions.nobrace: 'true'
2019-03-18T13:16:40.4980812Z ##[debug]matchOptions.noglobstar: 'undefined'
2019-03-18T13:16:40.4982485Z ##[debug]matchOptions.dot: 'true'
2019-03-18T13:16:40.4983626Z ##[debug]matchOptions.noext: 'undefined'
2019-03-18T13:16:40.4984882Z ##[debug]matchOptions.nocase: 'true'
2019-03-18T13:16:40.4985719Z ##[debug]matchOptions.nonull: 'undefined'
2019-03-18T13:16:40.4986500Z ##[debug]matchOptions.matchBase: 'undefined'
2019-03-18T13:16:40.4987259Z ##[debug]matchOptions.nocomment: 'undefined'
2019-03-18T13:16:40.4988040Z ##[debug]matchOptions.nonegate: 'undefined'
2019-03-18T13:16:40.4988825Z ##[debug]matchOptions.flipNegate: 'undefined'
2019-03-18T13:16:40.5045173Z ##[debug]pattern: 'bin/**/*.dll'
2019-03-18T13:16:40.5127784Z ##[debug]findPath: 'C:\BuildAgent\_work\1\a\bin'
2019-03-18T13:16:40.5128724Z ##[debug]statOnly: 'false'
2019-03-18T13:16:40.5149367Z ##[debug]findPath: 'C:\BuildAgent\_work\1\a\bin'
2019-03-18T13:16:40.5150348Z ##[debug]findOptions.followSpecifiedSymbolicLink: 'true'
2019-03-18T13:16:40.5151181Z ##[debug]findOptions.followSymbolicLinks: 'true'
<snip>output of lots of filenames</snip>
2019-03-18T13:16:40.6244800Z ##[debug]418 results
2019-03-18T13:16:40.6246014Z ##[debug]found 418 paths
2019-03-18T13:16:40.6246810Z ##[debug]applying include pattern
2019-03-18T13:16:40.6247658Z ##[debug]adjustedPattern: 'C:\BuildAgent\_work\1\a\bin/**/*.dll'
2019-03-18T13:16:40.6470900Z ##[debug]85 matches
2019-03-18T13:16:40.6482155Z ##[debug]85 final results
2019-03-18T13:16:40.6534691Z [command]C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 C:\BuildAgent\_work\1\a\bin\*.dll
2019-03-18T13:16:41.0233622Z SignTool Error: An error occurred while attempting to load the signing
2019-03-18T13:16:41.0234460Z 
2019-03-18T13:16:41.0235230Z    certificate from: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:41.0235740Z 
2019-03-18T13:16:41.0344390Z Error attempting to sign. Attempt number: 0. Exception text: Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:16:41.0348152Z Sleeping for 15 second(s)
2019-03-18T13:16:56.0395275Z [command]C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 C:\BuildAgent\_work\1\a\bin\*.dll
2019-03-18T13:16:56.1134897Z SignTool Error: An error occurred while attempting to load the signing
2019-03-18T13:16:56.1135592Z 
2019-03-18T13:16:56.1136102Z    certificate from: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:16:56.1136493Z 
2019-03-18T13:16:56.1179936Z Error attempting to sign. Attempt number: 1. Exception text: Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:16:56.1180941Z Sleeping for 15 second(s)
2019-03-18T13:17:11.1214844Z [command]C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 C:\BuildAgent\_work\1\a\bin\*.dll
2019-03-18T13:17:11.1749104Z SignTool Error: An error occurred while attempting to load the signing
2019-03-18T13:17:11.1749954Z 
2019-03-18T13:17:11.1750924Z    certificate from: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:11.1751509Z 
2019-03-18T13:17:11.1821558Z Error attempting to sign. Attempt number: 2. Exception text: Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:11.1822615Z Sleeping for 15 second(s)
2019-03-18T13:17:26.1836913Z [command]C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 C:\BuildAgent\_work\1\a\bin\*.dll
2019-03-18T13:17:26.2595740Z SignTool Error: An error occurred while attempting to load the signing
2019-03-18T13:17:26.2596728Z 
2019-03-18T13:17:26.2597253Z    certificate from: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:26.2597646Z 
2019-03-18T13:17:26.2640057Z Error attempting to sign. Attempt number: 3. Exception text: Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:26.2641702Z Sleeping for 15 second(s)
2019-03-18T13:17:41.2671049Z [command]C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx /p *** /fd sha256 C:\BuildAgent\_work\1\a\bin\*.dll
2019-03-18T13:17:41.3212735Z SignTool Error: An error occurred while attempting to load the signing
2019-03-18T13:17:41.3213754Z 
2019-03-18T13:17:41.3214294Z    certificate from: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:41.3214747Z 
2019-03-18T13:17:41.3255087Z Error attempting to sign. Attempt number: 4. Exception text: Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:41.3256669Z Sleeping for 15 second(s)
2019-03-18T13:17:56.3266342Z ##[debug]task result: Failed
2019-03-18T13:17:56.3268224Z ##[error]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3270156Z ##[debug]Processed: ##vso[task.issue type=error;]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3272375Z ##[debug]Processed: ##vso[task.complete result=Failed;]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3273514Z ##[debug]task result: Failed
2019-03-18T13:17:56.3274949Z ##[error]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3276470Z ##[debug]Processed: ##vso[task.issue type=error;]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3278290Z ##[debug]Processed: ##vso[task.complete result=Failed;]Unable to sign Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3431518Z ##[debug]secure file name for id 5c45de5a-1cfd-4206-b09b-c4565372bfc4 = CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:56.3433787Z ##[debug]Agent.TempDirectory=C:\BuildAgent\_work\_temp
2019-03-18T13:17:56.3436370Z ##[debug]Absolute path for pathSegments: C:\BuildAgent\_work\_temp,CodeSignCertificate-2022-02-20.pfx = C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:56.3438490Z ##[debug]Deleting secure file at: C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:56.3442904Z ##[debug]rm -rf C:\BuildAgent\_work\_temp\CodeSignCertificate-2022-02-20.pfx
2019-03-18T13:17:56.3444072Z ##[debug]removing file
2019-03-18T13:17:56.3729466Z (node:7104) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: C:\BuildAgent\_work\_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1
2019-03-18T13:17:56.3860841Z ##[section]Finishing: Authenticode Sign
dnperfors commented 5 years ago

I tried to get more information by passing /debug as additional argument, but it doesn't give any additional output.

The strange thing is that we have a separate build definition for another branch which is constantly passing, while this build definition on our master branch is constantly failing... They use exactly the same certificate, agents, etc.

pswetz commented 5 years ago

We also experience this issue quite a bit. Sometimes everything is fine, other times we end up with this error in multiple pipelines.

[debug]Evaluating condition for step: 'Authenticode Sign engine'

[debug]Evaluating: SucceededNode()

[debug]Evaluating SucceededNode:

[debug]=> True

[debug]Result: True

[section]Starting: Authenticode Sign engine

============================================================================== Task : Authenticode Sign Description : Authenticode sign executable code. Version : 3.0.0 Author : Michael Barry Help :

[debug]agent.TempDirectory=D:\a_temp

[debug]loading inputs and endpoints

[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN

[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION

[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION

[debug]loading INPUT_CERTIFICATELOCATION

[debug]loading INPUT_CERTIFICATESELECTIONMETHOD

[debug]loading INPUT_FILEALGO

[debug]loading INPUT_FILEPATH

[debug]loading INPUT_PFXFILE

[debug]loading INPUT_PFXPASSWORD

[debug]loading INPUT_PFXSECUREFILE

[debug]loading INPUT_RETRYCOUNT

[debug]loading INPUT_SIGNROOTPATH

[debug]loading INPUT_TIMESTAMPALGO

[debug]loading INPUT_TIMESTAMPSERVER

[debug]loading INPUT_TIMESTAMPSERVERDELAY

[debug]loading SECRET_PROD-CERT-PFX-KEY-PWD

[debug]loading SECRET_SYSTEM_ACCESSTOKEN

[debug]loading SECRET_TEST-CERT-PFX-KEY-PWD

[debug]loading SECUREFILE_TICKET_0d25dafe-1442-4810-8be3-ce6625abc914

[debug]loaded 19

[debug]Agent.ProxyUrl=undefined

[debug]Agent.CAInfo=undefined

[debug]Agent.ClientCert=undefined

[debug]signToolLocation=null

[debug]Using tool location: D:\a_tasks\authenticode-sign_xxxxxxxxx\3.0.0\x64\signtool.exe

[debug]check path : D:\a_tasks\authenticode-sign_xxxxxxxx\3.0.0\x64\signtool.exe

[debug]retryCount=5

[debug]timestampServerDelay=15

[debug]which 'D:\a_tasks\authenticode-sign_xxxxxx\3.0.0\x64\signtool.exe'

[debug]found: 'D:\a_tasks\authenticode-sign_xxxxxx\3.0.0\x64\signtool.exe'

[debug]which 'D:\a_tasks\authenticode-sign_xxxxxx\3.0.0\x64\signtool.exe'

[debug]found: 'D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe'

[debug]timestampServer=http://timestamp.digicert.com

[debug]timestampAlgo=sha256

[debug]certificateLocation=secureFile

[debug]pfxSecureFile=xxxxxxxxxxxx

[debug]System.TeamFoundationCollectionUri=https://xxxxxxxx.visualstudio.com/

[debug]SYSTEMVSSCONNECTION auth param ACCESSTOKEN = ***

[debug]secure file name for id xxxx = acmetestcert.pfx

[debug]Agent.TempDirectory=D:\a_temp

[debug]Absolute path for pathSegments: D:\a_temp,acmetestcert.pfx = D:\a_temp\acmetestcert.pfx

[debug]Downloading secure file contents to: D:\a_temp\acmetestcert.pfx

[debug]SYSTEM.TEAMPROJECT=Pathfinder

[debug]secure file ticket for id xxxxxxx = ***

[debug]Downloaded secure file contents to: D:\a_temp\acmetestcert.pfx

[debug]check path : D:\a_temp\acmetestcert.pfx

[debug]pfxPassword=***

[debug]additionalArguments=null

[debug]fileAlgo=sha256

[debug]filePath=engine.exe

[debug]signRootPath=D:\a\1\s\source\xxxxxx\bin\Release-Dev

[debug]defaultRoot: 'D:\a\1\s\source\xxxxx\bin\Release-Dev'

[debug]findOptions.followSpecifiedSymbolicLink: 'true'

[debug]findOptions.followSymbolicLinks: 'true'

[debug]matchOptions.debug: 'false'

[debug]matchOptions.nobrace: 'true'

[debug]matchOptions.noglobstar: 'undefined'

[debug]matchOptions.dot: 'true'

[debug]matchOptions.noext: 'undefined'

[debug]matchOptions.nocase: 'true'

[debug]matchOptions.nonull: 'undefined'

[debug]matchOptions.matchBase: 'undefined'

[debug]matchOptions.nocomment: 'undefined'

[debug]matchOptions.nonegate: 'undefined'

[debug]matchOptions.flipNegate: 'undefined'

[debug]pattern: 'engine.exe'

[debug]findPath: 'D:\a\1\s\source\PosApiBootstrapper\bin\Release-Dev\engine.exe'

[debug]statOnly: 'true'

[debug]found 1 paths

[debug]applying include pattern

[debug]adjustedPattern: 'D:\a\1\s\source\PosApiBootstrapper\bin\Release-Dev\engine.exe'

[debug]1 matches

[debug]1 final results

[command]D:\a_tasks\authenticode-sign_xxxxxxxx\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f D:\a_temp\acmetestcert.pfx /p *** /fd sha256 D:\a\1\s\source\xxxxxxx\bin\Release-Dev\engine.exe SignTool Error: An error occurred while attempting to load the signing

certificate from: D:\a\_temp\acmetestcert.pfx

Error attempting to sign. Attempt number: 0. Exception text: Error: D:\a_tasks\authenticode-sign_xxxxxx\3.0.0\x64\signtool.exe failed with return code: 1 Sleeping for 15 second(s) [command]D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f D:\a_temp\acmetestcert.pfx /p *** /fd sha256 D:\a\1\s\source\xxxxxxx\bin\Release-Dev\engine.exe SignTool Error: An error occurred while attempting to load the signing

certificate from: D:\a\_temp\acmetestcert.pfx

Error attempting to sign. Attempt number: 1. Exception text: Error: D:\a_tasks\authenticode-sign_xxxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1 Sleeping for 15 second(s) [command]D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f D:\a_temp\acmetestcert.pfx /p *** /fd sha256 D:\a\1\s\source\xxxxxxxxx\bin\Release-Dev\engine.exe SignTool Error: An error occurred while attempting to load the signing

certificate from: D:\a\_temp\acmetestcert.pfx

Error attempting to sign. Attempt number: 2. Exception text: Error: D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1 Sleeping for 15 second(s) [command]D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f D:\a_temp\acmetestcert.pfx /p *** /fd sha256 D:\a\1\s\source\PosApiBootstrapper\bin\Release-Dev\engine.exe SignTool Error: An error occurred while attempting to load the signing

certificate from: D:\a\_temp\acmetestcert.pfx

Error attempting to sign. Attempt number: 3. Exception text: Error: D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1 Sleeping for 15 second(s) [command]D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe sign /tr http://timestamp.digicert.com /td sha256 /f D:\a_temp\acmetestcert.pfx /p *** /fd sha256 D:\a\1\s\source\xxxxxxx\bin\Release-Dev\engine.exe SignTool Error: An error occurred while attempting to load the signing

certificate from: D:\a\_temp\acmetestcert.pfx

Error attempting to sign. Attempt number: 4. Exception text: Error: D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1 Sleeping for 15 second(s)

[debug]task result: Failed

[error]Unable to sign Error: D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1

[debug]Processed: ##vso[task.issue type=error;]Unable to sign Error: D:\a_tasks\authenticode-sign_xxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1

[debug]Processed: ##vso[task.complete result=Failed;]Unable to sign Error: D:\a_tasks\authenticode-sign_xxxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1

[debug]task result: Failed

[error]Unable to sign Error: D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1

[debug]Processed: ##vso[task.issue type=error;]Unable to sign Error: D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1

[debug]Processed: ##vso[task.complete result=Failed;]Unable to sign Error: D:\a_tasks\authenticode-sign_752fe535-ed47-4c2c-afcf-0778adb0bb12\3.0.0\x64\signtool.exe failed with return code: 1

[debug]secure file name for id 0d25dafe-1442-4810-8be3-ce6625abc914 = acmetestcert.pfx

[debug]Agent.TempDirectory=D:\a_temp

[debug]Absolute path for pathSegments: D:\a_temp,acmetestcert.pfx = D:\a_temp\acmetestcert.pfx

[debug]Deleting secure file at: D:\a_temp\acmetestcert.pfx

[debug]rm -rf D:\a_temp\acmetestcert.pfx

[debug]removing file

(node:2532) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: D:\a_tasks\authenticode-sign_xxxxxxxxxx\3.0.0\x64\signtool.exe failed with return code: 1

[section]Finishing: Authenticode Sign engine

jabbera commented 5 years ago

Based on this new log I wonder if the pfx isn't being downloaded properly. Can you try subbing out my home grown secure file feature with the official one?

https://docs.microsoft.com/en-us/azure/devops/pipelines/tasks/utility/download-secure-file?view=azure-devops

dnperfors commented 5 years ago

I tried to use the download-secure-file tasks and the first try did work.. I will change some other builds, and make sure it consistently works.

Update: after a day of building a lot of builds, it seems to work consistently. However, now that I think of it, I believe the problems started when our IT department moved TFS to an other server, so there might be an issue there instead, since we have several other issues since that time.

Funny enough, the download-secure-file doesn't show up in the the log at all... (actually the task is run as one of the first steps in the build, not where I had expected it...)

zauggm commented 5 years ago

I have also been experiencing this issue and can reproduce it quite easily. We have some builds that take quite a bit of time to complete and that seems to be what causes the issue. I've found that any signing step that tries to execute more than 20 minutes after the start of the build will fail with the error that other posters provided above. I have a build that floats around that 20 minute time range. If the signing step occurs before 20 minutes it succeeds. If the signing step occurs after 20 minutes it fails.

I did try using official download secure file task in my pipeline but it did not solve the issue.

Any thoughts on if this 20 minute timeout could be within the authenticode task?

jabbera commented 4 years ago

Cleaning up. Please let me know if you still see this issue with 5.0.4.

pswetz commented 4 years ago

We abandoned authenticode and deployed https://github.com/dotnet/SignService to handle our signing because of these issues.