Skip to content
This repository was archived by the owner on Jan 30, 2025. It is now read-only.

Commit 758d14b

Browse files
inancgumusinancgumus
authored
Merge pull request #151 from grafana/fix/improve-logs-20211203
Improve logs 20211203 (cherry picked)
2 parents b11bde2 + 4b09243 commit 758d14b

14 files changed

+940
-240
lines changed

‎common/barrier_test.go

Lines changed: 14 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -29,17 +29,18 @@ import (
2929
)
3030

3131
func TestBarrier(t *testing.T) {
32-
t.Run("should work", func(t *testing.T) {
33-
ctx := context.Background()
34-
timeoutSetings := NewTimeoutSettings(nil)
35-
frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil))
36-
frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789"))
37-
38-
barrier := NewBarrier()
39-
barrier.AddFrameNavigation(frame)
40-
frame.emit(EventFrameNavigation, "some data")
41-
42-
err := barrier.Wait(ctx)
43-
require.Nil(t, err)
44-
})
32+
ctx := context.Background()
33+
34+
log := NewLogger(ctx, NullLogger(), false, nil)
35+
36+
timeoutSetings := NewTimeoutSettings(nil)
37+
frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, log)
38+
frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789"), log)
39+
40+
barrier := NewBarrier()
41+
barrier.AddFrameNavigation(frame)
42+
frame.emit(EventFrameNavigation, "some data")
43+
44+
err := barrier.Wait(ctx)
45+
require.Nil(t, err)
4546
}

‎common/browser.go

Lines changed: 21 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -108,7 +108,7 @@ func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *B
108108
}
109109

110110
func (b *Browser) connect() error {
111-
b.logger.Debugf("Browser:connect", "wsURL:%v", b.browserProc.WsURL())
111+
b.logger.Debugf("Browser:connect", "wsURL:%q", b.browserProc.WsURL())
112112
var err error
113113
b.conn, err = NewConnection(b.ctx, b.browserProc.WsURL(), b.logger)
114114
if err != nil {
@@ -203,13 +203,13 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
203203
if ok {
204204
browserCtx = bctx
205205
}
206-
b.logger.Debugf("Browser:onAttachedToTarget", "sid:%v tid:%v bcid:%v bctx nil=%t", ev.SessionID, ev.TargetInfo.TargetID, ev.TargetInfo.BrowserContextID, bctx == nil)
206+
b.logger.Debugf("Browser:onAttachedToTarget", "sid:%v tid:%v bctxid:%v bctx nil=%t", ev.SessionID, ev.TargetInfo.TargetID, ev.TargetInfo.BrowserContextID, bctx == nil)
207207
b.contextsMu.RUnlock()
208208

209209
// We're not interested in the top-level browser target, other targets or DevTools targets right now.
210210
isDevTools := strings.HasPrefix(ev.TargetInfo.URL, "devtools://devtools")
211211
if ev.TargetInfo.Type == "browser" || ev.TargetInfo.Type == "other" || isDevTools {
212-
b.logger.Debugf("Browser:onAttachedToTarget", "sid:%v tid:%v, returns: devtools", ev.SessionID, ev.TargetInfo.TargetID)
212+
b.logger.Debugf("Browser:onAttachedToTarget:return", "sid:%v tid:%v (devtools)", ev.SessionID, ev.TargetInfo.TargetID)
213213
return
214214
}
215215

@@ -219,18 +219,18 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
219219
isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected()
220220
if _, ok := err.(*websocket.CloseError); !ok && !isRunning {
221221
// If we're no longer connected to browser, then ignore WebSocket errors
222-
b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, returns: websocket err: %v",
222+
b.logger.Debugf("Browser:onAttachedToTarget:background_page:return", "sid:%v tid:%v websocket err:%v",
223223
ev.SessionID, ev.TargetInfo.TargetID, err)
224224
return
225225
}
226226
k6Throw(b.ctx, "cannot create NewPage for background_page event: %w", err)
227227
}
228228
b.pagesMu.Lock()
229-
b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding tid", ev.SessionID, ev.TargetInfo.TargetID)
229+
b.logger.Debugf("Browser:onAttachedToTarget:background_page:addTid", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
230230
b.pages[ev.TargetInfo.TargetID] = p
231231
b.pagesMu.Unlock()
232232
b.sessionIDtoTargetIDMu.Lock()
233-
b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding sid", ev.SessionID, ev.TargetInfo.TargetID)
233+
b.logger.Debugf("Browser:onAttachedToTarget:background_page:addSid", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
234234
b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
235235
b.sessionIDtoTargetIDMu.Unlock()
236236
} else if ev.TargetInfo.Type == "page" {
@@ -246,17 +246,17 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
246246
isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected()
247247
if _, ok := err.(*websocket.CloseError); !ok && !isRunning {
248248
// If we're no longer connected to browser, then ignore WebSocket errors
249-
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, returns: websocket error", ev.SessionID, ev.TargetInfo.TargetID)
249+
b.logger.Debugf("Browser:onAttachedToTarget:page:return", "sid:%v tid:%v websocket err:", ev.SessionID, ev.TargetInfo.TargetID)
250250
return
251251
}
252252
k6Throw(b.ctx, "cannot create NewPage for page event: %w", err)
253253
}
254254
b.pagesMu.Lock()
255-
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, adding page as a target", ev.SessionID, ev.TargetInfo.TargetID)
255+
b.logger.Debugf("Browser:onAttachedToTarget:page:addTarget", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
256256
b.pages[ev.TargetInfo.TargetID] = p
257257
b.pagesMu.Unlock()
258258
b.sessionIDtoTargetIDMu.Lock()
259-
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, changing sid to tid", ev.SessionID, ev.TargetInfo.TargetID)
259+
b.logger.Debugf("Browser:onAttachedToTarget:page:sidToTid", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
260260
b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
261261
b.sessionIDtoTargetIDMu.Unlock()
262262
browserCtx.emit(EventBrowserContextPage, p)
@@ -266,18 +266,21 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
266266
func (b *Browser) onDetachedFromTarget(ev *target.EventDetachedFromTarget) {
267267
b.sessionIDtoTargetIDMu.RLock()
268268
targetID, ok := b.sessionIDtoTargetID[ev.SessionID]
269+
269270
b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v", ev.SessionID, targetID)
271+
defer b.logger.Debugf("Browser:onDetachedFromTarget:return", "sid:%v tid:%v", ev.SessionID, targetID)
272+
270273
b.sessionIDtoTargetIDMu.RUnlock()
271274
if !ok {
272-
b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v, returns", ev.SessionID, targetID)
273275
// We don't track targets of type "browser", "other" and "devtools", so ignore if we don't recognize target.
274276
return
275277
}
276278

277279
b.pagesMu.Lock()
278280
defer b.pagesMu.Unlock()
279281
if t, ok := b.pages[targetID]; ok {
280-
b.logger.Debugf("Browser:onDetachedFromTarget", "tid:%v, delete page", targetID)
282+
b.logger.Debugf("Browser:onDetachedFromTarget:deletePage", "sid:%v tid:%v", ev.SessionID, targetID)
283+
281284
delete(b.pages, targetID)
282285
t.didClose()
283286
}
@@ -303,7 +306,7 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
303306
func(data interface{}) bool {
304307
mu.RLock()
305308
defer mu.RUnlock()
306-
b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, createWaitForEventHandler", targetID, id)
309+
b.logger.Debugf("Browser:newPageInContext:createWaitForEventHandler", "tid:%v bctxid:%v", targetID, id)
307310
return data.(*Page).targetID == targetID
308311
},
309312
)
@@ -314,20 +317,20 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
314317
mu.Lock()
315318
defer mu.Unlock()
316319
localTargetID = targetID
317-
b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, CreateTarget(blank)", localTargetID, id)
320+
b.logger.Debugf("Browser:newPageInContext:CreateTargetBlank", "tid:%v bctxid:%v", localTargetID, id)
318321
if targetID, err = action.Do(cdp.WithExecutor(b.ctx, b.conn)); err != nil {
319322
errCh <- fmt.Errorf("unable to execute %T: %w", action, err)
320323
}
321324
}()
322325
select {
323326
case <-b.ctx.Done():
324-
b.logger.Debugf("Browser:newPageInContext:<-b.ctx.Done", "tid:%v bcid:%v", localTargetID, id)
327+
b.logger.Debugf("Browser:newPageInContext:<-b.ctx.Done", "tid:%v bctxid:%v", localTargetID, id)
325328
case <-time.After(b.launchOpts.Timeout):
326-
b.logger.Debugf("Browser:newPageInContext:timeout", "tid:%v bcid:%v timeout:%s", localTargetID, id, b.launchOpts.Timeout)
329+
b.logger.Debugf("Browser:newPageInContext:timeout", "tid:%v bctxid:%v timeout:%s", localTargetID, id, b.launchOpts.Timeout)
327330
case c := <-ch:
328-
b.logger.Debugf("Browser:newPageInContext:<-ch", "tid:%v bcid:%v, c:%v", localTargetID, id, c)
331+
b.logger.Debugf("Browser:newPageInContext:<-ch", "tid:%v bctxid:%v, c:%v", localTargetID, id, c)
329332
case err := <-errCh:
330-
b.logger.Debugf("Browser:newPageInContext:<-errCh", "tid:%v bcid:%v, err:%v", localTargetID, id, err)
333+
b.logger.Debugf("Browser:newPageInContext:<-errCh", "tid:%v bctxid:%v, err:%v", localTargetID, id, err)
331334
return nil, err
332335
}
333336
b.pagesMu.RLock()
@@ -378,7 +381,7 @@ func (b *Browser) IsConnected() bool {
378381
func (b *Browser) NewContext(opts goja.Value) api.BrowserContext {
379382
action := target.CreateBrowserContext().WithDisposeOnDetach(true)
380383
browserContextID, err := action.Do(cdp.WithExecutor(b.ctx, b.conn))
381-
b.logger.Debugf("Browser:NewContext", "browserContextID: %v", browserContextID)
384+
b.logger.Debugf("Browser:NewContext", "bctxid:%v", browserContextID)
382385
if err != nil {
383386
k6Throw(b.ctx, "cannot create browser context (%s): %w", browserContextID, err)
384387
}
@@ -390,7 +393,6 @@ func (b *Browser) NewContext(opts goja.Value) api.BrowserContext {
390393

391394
b.contextsMu.Lock()
392395
defer b.contextsMu.Unlock()
393-
b.logger.Debugf("Browser:NewContext", "NewBrowserContext: %v", browserContextID)
394396
browserCtx := NewBrowserContext(b.ctx, b.conn, b, browserContextID, browserCtxOpts, b.logger)
395397
b.contexts[browserContextID] = browserCtx
396398

‎common/browser_context.go

Lines changed: 46 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ import (
2929
cdpbrowser "github.com/chromedp/cdproto/browser"
3030
"github.com/chromedp/cdproto/cdp"
3131
"github.com/chromedp/cdproto/storage"
32+
"github.com/chromedp/cdproto/target"
3233
"github.com/dop251/goja"
3334
"github.com/grafana/xk6-browser/api"
3435
k6common "go.k6.io/k6/js/common"
@@ -77,7 +78,7 @@ func (b *BrowserContext) AddCookies(cookies goja.Value) {
7778

7879
// AddInitScript adds a script that will be initialized on all new pages.
7980
func (b *BrowserContext) AddInitScript(script goja.Value, arg goja.Value) {
80-
b.logger.Debugf("BrowserContext:AddInitScript", "")
81+
b.logger.Debugf("BrowserContext:AddInitScript", "bctxid:%v", b.id)
8182

8283
rt := k6common.GetRuntime(b.ctx)
8384

@@ -118,6 +119,8 @@ func (b *BrowserContext) Browser() api.Browser {
118119

119120
// ClearCookies clears cookies.
120121
func (b *BrowserContext) ClearCookies() {
122+
b.logger.Debugf("BrowserContext:ClearCookies", "bctxid:%v", b.id)
123+
121124
action := storage.ClearCookies().WithBrowserContextID(b.id)
122125
if err := action.Do(b.ctx); err != nil {
123126
k6Throw(b.ctx, "unable to clear cookies permissions: %w", err)
@@ -126,6 +129,8 @@ func (b *BrowserContext) ClearCookies() {
126129

127130
// ClearPermissions clears any permission overrides.
128131
func (b *BrowserContext) ClearPermissions() {
132+
b.logger.Debugf("BrowserContext:ClearPermissions", "bctxid:%v", b.id)
133+
129134
action := cdpbrowser.ResetPermissions().WithBrowserContextID(b.id)
130135
if err := action.Do(b.ctx); err != nil {
131136
k6Throw(b.ctx, "unable to clear override permissions: %w", err)
@@ -134,6 +139,8 @@ func (b *BrowserContext) ClearPermissions() {
134139

135140
// Close shuts down the browser context.
136141
func (b *BrowserContext) Close() {
142+
b.logger.Debugf("BrowserContext:Close", "bctxid:%v", b.id)
143+
137144
if b.id == "" {
138145
k6Throw(b.ctx, "default browser context can't be closed")
139146
}
@@ -157,7 +164,8 @@ func (b *BrowserContext) ExposeFunction(name string, callback goja.Callable) {
157164

158165
// GrantPermissions enables the specified permissions, all others will be disabled.
159166
func (b *BrowserContext) GrantPermissions(permissions []string, opts goja.Value) {
160-
b.logger.Debugf("BrowserContext:GrantPermissions", "")
167+
b.logger.Debugf("BrowserContext:GrantPermissions", "bctxid:%v", b.id)
168+
161169
permsToProtocol := map[string]cdpbrowser.PermissionType{
162170
"geolocation": cdpbrowser.PermissionTypeGeolocation,
163171
"midi": cdpbrowser.PermissionTypeMidi,
@@ -207,12 +215,25 @@ func (b *BrowserContext) NewCDPSession() api.CDPSession {
207215

208216
// NewPage creates a new page inside this browser context.
209217
func (b *BrowserContext) NewPage() api.Page {
210-
b.logger.Debugf("BrowserContext:NewPage", "bid:%v", b.id)
218+
b.logger.Debugf("BrowserContext:NewPage", "bctxid:%v", b.id)
219+
211220
p, err := b.browser.newPageInContext(b.id)
212221
if err != nil {
213222
k6Throw(b.ctx, "cannot create a new page: %w", err)
214223
}
215-
b.logger.Debugf("BrowserContext:NewPage:returns", "bid:%v ptid:%s", b.id, p.targetID)
224+
225+
var (
226+
bctxid cdp.BrowserContextID
227+
ptid target.ID
228+
)
229+
if b != nil {
230+
bctxid = b.id
231+
}
232+
if p != nil {
233+
ptid = p.targetID
234+
}
235+
b.logger.Debugf("BrowserContext:NewPage:return", "bctxid:%v ptid:%s", bctxid, ptid)
236+
216237
return p
217238
}
218239

@@ -231,11 +252,15 @@ func (b *BrowserContext) Route(url goja.Value, handler goja.Callable) {
231252

232253
// SetDefaultNavigationTimeout sets the default navigation timeout in milliseconds.
233254
func (b *BrowserContext) SetDefaultNavigationTimeout(timeout int64) {
255+
b.logger.Debugf("BrowserContext:SetDefaultNavigationTimeout", "bctxid:%v timeout:%d", b.id, timeout)
256+
234257
b.timeoutSettings.setDefaultNavigationTimeout(timeout)
235258
}
236259

237260
// SetDefaultTimeout sets the default maximum timeout in milliseconds.
238261
func (b *BrowserContext) SetDefaultTimeout(timeout int64) {
262+
b.logger.Debugf("BrowserContext:SetDefaultTimeout", "bctxid:%v timeout:%d", b.id, timeout)
263+
239264
b.timeoutSettings.setDefaultTimeout(timeout)
240265
}
241266

@@ -245,6 +270,8 @@ func (b *BrowserContext) SetExtraHTTPHeaders(headers map[string]string) {
245270

246271
// SetGeolocation overrides the geo location of the user.
247272
func (b *BrowserContext) SetGeolocation(geolocation goja.Value) {
273+
b.logger.Debugf("BrowserContext:SetGeolocation", "bctxid:%v", b.id)
274+
248275
g := NewGeolocation()
249276
if err := g.Parse(b.ctx, geolocation); err != nil {
250277
k6Throw(b.ctx, "cannot parse geo location: %w", err)
@@ -260,6 +287,8 @@ func (b *BrowserContext) SetGeolocation(geolocation goja.Value) {
260287

261288
// SetHTTPCredentials sets username/password credentials to use for HTTP authentication.
262289
func (b *BrowserContext) SetHTTPCredentials(httpCredentials goja.Value) {
290+
b.logger.Debugf("BrowserContext:SetHTTPCredentials", "bctxid:%v", b.id)
291+
263292
c := NewCredentials()
264293
if err := c.Parse(b.ctx, httpCredentials); err != nil {
265294
k6Throw(b.ctx, "cannot set HTTP credentials: %w", err)
@@ -273,6 +302,8 @@ func (b *BrowserContext) SetHTTPCredentials(httpCredentials goja.Value) {
273302

274303
// SetOffline toggles the browser's connectivity on/off.
275304
func (b *BrowserContext) SetOffline(offline bool) {
305+
b.logger.Debugf("BrowserContext:SetOffline", "bctxid:%v offline:%t", b.id, offline)
306+
276307
b.opts.Offline = offline
277308
for _, p := range b.browser.getPages() {
278309
p.updateOffline()
@@ -288,8 +319,8 @@ func (b *BrowserContext) Unroute(url goja.Value, handler goja.Callable) {
288319
}
289320

290321
func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value) interface{} {
291-
b.logger.Debugf("BrowserContext:WaitForEvent", "event:%q", event)
292322
// TODO: This public API needs Promise support (as return value) to be useful in JS!
323+
b.logger.Debugf("BrowserContext:WaitForEvent", "bctxid:%v event:%q", b.id, event)
293324

294325
rt := k6common.GetRuntime(b.ctx)
295326

@@ -325,16 +356,16 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value)
325356
ch := make(chan interface{})
326357

327358
go func() {
328-
b.logger.Debugf("BrowserContext:WaitForEvent:go()", "starts")
329-
defer b.logger.Debugf("BrowserContext:WaitForEvent:go()", "returns")
359+
b.logger.Debugf("BrowserContext:WaitForEvent:go():starts", "bctxid:%v", b.id)
360+
defer b.logger.Debugf("BrowserContext:WaitForEvent:go():returns", "bctxid:%v", b.id)
330361
for {
331362
select {
332363
case <-evCancelCtx.Done():
333-
b.logger.Debugf("BrowserContext:WaitForEvent:go()", "evCancelCtx done")
364+
b.logger.Debugf("BrowserContext:WaitForEvent:go():evCancelCtx:done", "bctxid:%v", b.id)
334365
return
335366
case ev := <-chEvHandler:
336367
if ev.typ == EventBrowserContextClose {
337-
b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextClose returns")
368+
b.logger.Debugf("BrowserContext:WaitForEvent:go():EventBrowserContextClose:return", "bctxid:%v", b.id)
338369
ch <- nil
339370
close(ch)
340371

@@ -344,11 +375,11 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value)
344375
return
345376
}
346377
if ev.typ == EventBrowserContextPage {
347-
b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextPage")
378+
b.logger.Debugf("BrowserContext:WaitForEvent:go():EventBrowserContextPage", "bctxid:%v", b.id)
348379
p := ev.data.(*Page)
349380
exported := k6common.Bind(rt, p, &b.ctx)
350381
if retVal, err := predicateFn(rt.ToValue(exported)); err == nil && retVal.ToBoolean() {
351-
b.logger.Debugf("BrowserContext:WaitForEvent:go()", "EventBrowserContextPage returns")
382+
b.logger.Debugf("BrowserContext:WaitForEvent:go():EventBrowserContextPage:return", "bctxid:%v", b.id)
352383
ch <- p
353384
close(ch)
354385

@@ -367,13 +398,13 @@ func (b *BrowserContext) WaitForEvent(event string, optsOrPredicate goja.Value)
367398

368399
select {
369400
case <-b.ctx.Done():
370-
b.logger.Debugf("BrowserContext:WaitForEvent", "b.ctx Done")
401+
b.logger.Debugf("BrowserContext:WaitForEvent:ctx.Done", "bctxid:%v event:%q", b.id, event)
371402
case <-time.After(timeout):
372-
b.logger.Debugf("BrowserContext:WaitForEvent", "timeout")
403+
b.logger.Debugf("BrowserContext:WaitForEvent:timeout", "bctxid:%v event:%q", b.id, event)
373404
case evData := <-ch:
374-
b.logger.Debugf("BrowserContext:WaitForEvent", "evData")
405+
b.logger.Debugf("BrowserContext:WaitForEvent:evData", "bctxid:%v event:%q", b.id, event)
375406
return evData
376407
}
377-
b.logger.Debugf("BrowserContext:WaitForEvent", "nil return")
408+
b.logger.Debugf("BrowserContext:WaitForEvent:return nil", "bctxid:%v event:%q", b.id, event)
378409
return nil
379410
}

0 commit comments

Comments
 (0)