@@ -13,6 +13,7 @@ import (
1313 "path/filepath"
1414 "strings"
1515 "syscall"
16+ "time"
1617
1718 "golang.org/x/crypto/ssh"
1819 "golang.org/x/crypto/ssh/agent"
@@ -223,22 +224,32 @@ func (a *filterAgent) Sign(key ssh.PublicKey, data []byte) (*ssh.Signature, erro
223224 if ! a .isAllowed (key ) {
224225 return nil , errors .New ("key not allowed" )
225226 }
227+ started := time .Now ()
226228 if err := a .auth .Authorize (key , a .commentFor (key ), 0 ); err != nil {
227229 return nil , err
228230 }
231+ log .Printf ("authorize finished after %s: %s" , time .Since (started ).Round (time .Millisecond ), ssh .FingerprintSHA256 (key ))
229232
230- return a .upstream .Sign (key , data )
233+ started = time .Now ()
234+ sig , err := a .upstream .Sign (key , data )
235+ log .Printf ("upstream sign finished after %s: %s" , time .Since (started ).Round (time .Millisecond ), ssh .FingerprintSHA256 (key ))
236+ return sig , err
231237}
232238
233239func (a * filterAgent ) SignWithFlags (key ssh.PublicKey , data []byte , flags agent.SignatureFlags ) (* ssh.Signature , error ) {
234240 if ! a .isAllowed (key ) {
235241 return nil , errors .New ("key not allowed" )
236242 }
243+ started := time .Now ()
237244 if err := a .auth .Authorize (key , a .commentFor (key ), flags ); err != nil {
238245 return nil , err
239246 }
247+ log .Printf ("authorize finished after %s flags=%d: %s" , time .Since (started ).Round (time .Millisecond ), flags , ssh .FingerprintSHA256 (key ))
240248
241- return a .upstream .SignWithFlags (key , data , flags )
249+ started = time .Now ()
250+ sig , err := a .upstream .SignWithFlags (key , data , flags )
251+ log .Printf ("upstream sign finished after %s flags=%d: %s" , time .Since (started ).Round (time .Millisecond ), flags , ssh .FingerprintSHA256 (key ))
252+ return sig , err
242253}
243254
244255func (a * filterAgent ) isAllowed (key ssh.PublicKey ) bool {
0 commit comments