@@ -6,12 +6,39 @@ const _ = require("lodash");
66const config = require ( "config" ) ;
77const HttpStatus = require ( "http-status-codes" ) ;
88const { v4 : uuid } = require ( 'uuid' ) ;
9+ const util = require ( "util" ) ;
910const helper = require ( "./src/common/helper" ) ;
1011const errors = require ( "./src/common/errors" ) ;
1112const logger = require ( "./src/common/logger" ) ;
1213const routes = require ( "./src/routes" ) ;
1314const authenticator = require ( "tc-core-library-js" ) . middleware . jwtAuthenticator ;
1415
16+ const sanitizeForLog = ( value ) => {
17+ const seen = new WeakSet ( ) ;
18+ try {
19+ return JSON . parse (
20+ JSON . stringify ( value , ( key , val ) => {
21+ if ( typeof val === "object" && val !== null ) {
22+ if ( seen . has ( val ) ) return "<circular>" ;
23+ seen . add ( val ) ;
24+ }
25+ if ( Buffer . isBuffer ( val ) ) return `<Buffer length=${ val . length } >` ;
26+ if ( val && typeof val === "object" && val . type === "Buffer" && Array . isArray ( val . data ) ) {
27+ return `<Buffer length=${ val . data . length } >` ;
28+ }
29+ if ( Array . isArray ( val ) && val . length > 30 ) return `Array(${ val . length } )` ;
30+ if ( typeof val === "string" && val . length > 500 ) return `${ val . slice ( 0 , 500 ) } ...<truncated>` ;
31+ return val ;
32+ } )
33+ ) ;
34+ } catch ( err ) {
35+ return `<unserializable: ${ err . message } >` ;
36+ }
37+ } ;
38+
39+ const safeInspect = ( payload ) => util . inspect ( sanitizeForLog ( payload ) , { breakLength : Infinity } ) ;
40+ const getSignature = ( req ) => req . signature || req . _reqLogId || "no-signature" ;
41+
1542/**
1643 * Configure all routes for express app
1744 * @param app the express app
@@ -31,14 +58,19 @@ module.exports = (app) => {
3158 if ( def . method !== "checkHealth" ) {
3259 req . _id = uuid ( ) ;
3360 req . signature = `${ req . _id } -${ def . controller } #${ def . method } ` ;
34- logger . info ( `Started request handling, ${ req . signature } ` ) ;
61+ logger . info (
62+ `Started request handling, ${ req . signature } ${ req . method } ${ req . originalUrl } controller=${ def . controller } .${ def . method } query=${ safeInspect (
63+ req . query
64+ ) } params=${ safeInspect ( req . params ) } body=${ safeInspect ( req . body ) } `
65+ ) ;
3566 }
3667 next ( ) ;
3768 } ) ;
3869
3970 actions . push ( ( req , res , next ) => {
4071 if ( _ . get ( req , "query.token" ) ) {
4172 _ . set ( req , "headers.authorization" , `Bearer ${ _ . trim ( req . query . token ) } ` ) ;
73+ logger . info ( `[${ getSignature ( req ) } ] Promoted query.token to Authorization header` ) ;
4274 }
4375 next ( ) ;
4476 } ) ;
@@ -53,13 +85,23 @@ module.exports = (app) => {
5385 if ( req . authUser . isMachine ) {
5486 // M2M
5587 if ( ! req . authUser . scopes || ! helper . checkIfExists ( def . scopes , req . authUser . scopes ) ) {
88+ logger . warn (
89+ `[${ getSignature ( req ) } ] Machine token scope mismatch. required=${ safeInspect (
90+ def . scopes
91+ ) } provided=${ safeInspect ( req . authUser . scopes ) } `
92+ ) ;
5693 next ( new errors . ForbiddenError ( `You are not allowed to perform this action, because the scopes are incorrect. \
5794 Required scopes: ${ JSON . stringify ( def . scopes ) } \
5895 Provided scopes: ${ JSON . stringify ( req . authUser . scopes ) } ` ) ) ;
5996 } else {
6097 req . authUser . handle = config . M2M_AUDIT_HANDLE ;
6198 req . authUser . userId = config . M2M_AUDIT_USERID ;
6299 req . userToken = req . headers . authorization . split ( " " ) [ 1 ] ;
100+ logger . info (
101+ `[${ getSignature ( req ) } ] Authenticated M2M token scopes=${ safeInspect (
102+ req . authUser . scopes
103+ ) } `
104+ ) ;
63105 next ( ) ;
64106 }
65107 } else {
@@ -73,15 +115,26 @@ module.exports = (app) => {
73115 _ . map ( req . authUser . roles , ( r ) => r . toLowerCase ( ) )
74116 )
75117 ) {
118+ logger . warn (
119+ `[${ getSignature ( req ) } ] User role mismatch required=${ safeInspect (
120+ def . access
121+ ) } provided=${ safeInspect ( req . authUser . roles ) } `
122+ ) ;
76123 next ( new errors . ForbiddenError ( `You are not allowed to perform this action, because the roles are incorrect. \
77124 Required roles: ${ JSON . stringify ( def . access ) } \
78125 Provided roles: ${ JSON . stringify ( req . authUser . roles ) } ` ) ) ;
79126 } else {
80127 // user token is used in create/update challenge to ensure user can create/update challenge under specific project
81128 req . userToken = req . headers . authorization . split ( " " ) [ 1 ] ;
129+ logger . info (
130+ `[${ getSignature ( req ) } ] Authenticated user=${ req . authUser . userId } roles=${ safeInspect (
131+ req . authUser . roles
132+ ) } `
133+ ) ;
82134 next ( ) ;
83135 }
84136 } else {
137+ logger . warn ( `[${ getSignature ( req ) } ] Authenticated user missing roles` ) ;
85138 next ( new errors . ForbiddenError ( "You are not authorized to perform this action, \
86139 because no roles were provided" ) ) ;
87140 }
@@ -90,43 +143,98 @@ module.exports = (app) => {
90143 } else {
91144 // public API, but still try to authenticate token if provided, but allow missing/invalid token
92145 actions . push ( ( req , res , next ) => {
146+ const hasToken =
147+ ! ! req . headers . authorization || ! ! _ . get ( req , "query.token" ) || ! ! req . authUser ;
148+ if ( ! hasToken ) {
149+ return next ( ) ;
150+ }
93151 const interceptRes = { } ;
94152 interceptRes . status = ( ) => interceptRes ;
95153 interceptRes . json = ( ) => interceptRes ;
96- interceptRes . send = ( ) => next ( ) ;
97- authenticator ( _ . pick ( config , [ "AUTH_SECRET" , "VALID_ISSUERS" ] ) ) ( req , interceptRes , next ) ;
154+ interceptRes . send = ( payload ) => {
155+ logger . info (
156+ `[${ getSignature ( req ) } ] Public route: authenticator send called payload=${ safeInspect (
157+ payload
158+ ) } `
159+ ) ;
160+ return next ( ) ;
161+ } ;
162+ const authMw = authenticator ( _ . pick ( config , [ "AUTH_SECRET" , "VALID_ISSUERS" ] ) ) ;
163+ let finished = false ;
164+ const bailoutTimer = setTimeout ( ( ) => {
165+ if ( finished ) return ;
166+ finished = true ;
167+ next ( ) ;
168+ } , 8000 ) ;
169+ authMw ( req , interceptRes , ( ...args ) => {
170+ if ( finished ) return ;
171+ finished = true ;
172+ clearTimeout ( bailoutTimer ) ;
173+ next ( ...args ) ;
174+ } ) ;
98175 } ) ;
99176
100177 actions . push ( ( req , res , next ) => {
101178 if ( ! req . authUser ) {
179+ logger . info ( `[${ getSignature ( req ) } ] Public route: no authUser context` ) ;
102180 next ( ) ;
103181 } else if ( req . authUser . isMachine ) {
104182 if (
105183 ! def . scopes ||
106184 ! req . authUser . scopes ||
107185 ! helper . checkIfExists ( def . scopes , req . authUser . scopes )
108186 ) {
187+ logger . info (
188+ `[${ getSignature ( req ) } ] Public route: dropping machine token due to scope mismatch`
189+ ) ;
109190 req . authUser = undefined ;
191+ } else {
192+ logger . info ( `[${ getSignature ( req ) } ] Public route: valid machine token attached` ) ;
110193 }
111194 next ( ) ;
112195 } else {
113196 req . authUser . userId = String ( req . authUser . userId ) ;
197+ logger . info (
198+ `[${ getSignature ( req ) } ] Public route: user present userId=${ req . authUser . userId } `
199+ ) ;
114200 next ( ) ;
115201 }
116202 } ) ;
117203 }
118- actions . push ( method ) ;
204+
205+ actions . push ( async ( req , res , next ) => {
206+ logger . info ( `[${ getSignature ( req ) } ] Invoking ${ def . controller } .${ def . method } ` ) ;
207+ try {
208+ const resultPromise = method ( req , res , next ) ;
209+ if ( resultPromise && typeof resultPromise . then === "function" ) {
210+ await resultPromise ;
211+ }
212+ logger . info (
213+ `[${ getSignature ( req ) } ] Completed ${ def . controller } .${ def . method } headersSent=${ res . headersSent } status=${ res . statusCode } `
214+ ) ;
215+ } catch ( err ) {
216+ logger . error (
217+ `[${ getSignature ( req ) } ] ${ def . controller } .${ def . method } threw error: ${
218+ err . message || "unknown error"
219+ } `
220+ ) ;
221+ throw err ;
222+ }
223+ } ) ;
224+
119225 app [ verb ] ( `/${ config . API_VERSION } ${ path } ` , helper . autoWrapExpress ( actions ) ) ;
120226 } ) ;
121227 } ) ;
122228
123229 // Check if the route is not found or HTTP method is not supported
124230 app . use ( ( req , res ) => {
125231 if ( routes [ req . baseUrl ] ) {
232+ logger . warn ( `Unsupported method ${ req . method } for ${ req . originalUrl } ` ) ;
126233 res . status ( HttpStatus . METHOD_NOT_ALLOWED ) . json ( {
127234 message : "The requested HTTP method is not supported." ,
128235 } ) ;
129236 } else {
237+ logger . warn ( `Route not found for ${ req . method } ${ req . originalUrl } ` ) ;
130238 res . status ( HttpStatus . NOT_FOUND ) . json ( {
131239 message : "The requested resource cannot be found." ,
132240 } ) ;
0 commit comments