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

Commit 99d1ec9

Browse files
inancgumusinancgumus
authored
Merge pull request #131 from grafana/fix/54-proper-logger
2 parents 016a170 + 19b9e48 commit 99d1ec9

15 files changed

+516
-180
lines changed

‎api/page.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ type Page interface {
2727
AddInitScript(script goja.Value, arg goja.Value)
2828
AddScriptTag(opts goja.Value)
2929
AddStyleTag(opts goja.Value)
30-
BrintToFront()
30+
BringToFront()
3131
Check(selector string, opts goja.Value)
3232
Click(selector string, opts goja.Value)
3333
Close(opts goja.Value)

‎chromium/browser_type.go

Lines changed: 40 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -24,11 +24,14 @@ import (
2424
"context"
2525
"errors"
2626
"fmt"
27+
"os"
28+
"regexp"
2729

2830
"github.com/dop251/goja"
2931
"github.com/grafana/xk6-browser/api"
3032
"github.com/grafana/xk6-browser/common"
3133
k6common "go.k6.io/k6/js/common"
34+
k6lib "go.k6.io/k6/lib"
3235
)
3336

3437
// Ensure BrowserType implements the api.BrowserType interface.
@@ -62,7 +65,7 @@ func NewBrowserType(ctx context.Context) api.BrowserType {
6265

6366
func (b *BrowserType) Connect(opts goja.Value) {
6467
rt := k6common.GetRuntime(b.Ctx)
65-
k6common.Throw(rt, errors.New("BrowserType.connect() has not been implemented yet!"))
68+
k6common.Throw(rt, errors.New("BrowserType.connect() has not been implemented yet"))
6669
}
6770

6871
func (b *BrowserType) ExecutablePath() string {
@@ -75,9 +78,13 @@ func (b *BrowserType) Launch(opts goja.Value) api.Browser {
7578

7679
launchOpts := common.NewLaunchOptions()
7780
launchOpts.Parse(b.Ctx, opts)
78-
7981
b.Ctx = common.WithLaunchOptions(b.Ctx, launchOpts)
8082

83+
envs := make([]string, len(launchOpts.Env))
84+
for k, v := range launchOpts.Env {
85+
envs = append(envs, fmt.Sprintf("%s=%s", k, v))
86+
}
87+
8188
flags := map[string]interface{}{
8289
//chromedp.ProxyServer(""),
8390
//chromedp.UserAgent(""),
@@ -118,22 +125,23 @@ func (b *BrowserType) Launch(opts goja.Value) api.Browser {
118125
"no-startup-window": true,
119126
}
120127

121-
envs := make([]string, len(launchOpts.Env))
122-
for k, v := range launchOpts.Env {
123-
envs = append(envs, fmt.Sprintf("%s=%s", k, v))
124-
}
125-
126128
allocator := NewAllocator(flags, envs)
127129
browserProc, err := allocator.Allocate(b.Ctx, launchOpts)
128130
if browserProc == nil {
129-
k6common.Throw(rt, fmt.Errorf("unable to allocate browser: %w", err))
131+
k6common.Throw(rt, fmt.Errorf("cannot allocate browser: %w", err))
130132
}
131133

134+
logger, err := makeLogger(b.Ctx, launchOpts)
135+
if err != nil {
136+
k6common.Throw(rt, fmt.Errorf("cannot make logger: %w", err))
137+
}
138+
browserProc.AttachLogger(logger)
139+
132140
// attach the browser process ID to the context
133141
// so that we can kill it afterward if it lingers
134142
// see: k6Throw function
135143
b.Ctx = common.WithProcessID(b.Ctx, browserProc.Pid())
136-
browser, err := common.NewBrowser(b.Ctx, b.CancelFn, browserProc, launchOpts)
144+
browser, err := common.NewBrowser(b.Ctx, b.CancelFn, browserProc, launchOpts, logger)
137145
if err != nil {
138146
k6common.Throw(rt, err)
139147
}
@@ -142,10 +150,32 @@ func (b *BrowserType) Launch(opts goja.Value) api.Browser {
142150

143151
func (b *BrowserType) LaunchPersistentContext(userDataDir string, opts goja.Value) api.Browser {
144152
rt := k6common.GetRuntime(b.Ctx)
145-
k6common.Throw(rt, errors.New("BrowserType.LaunchPersistentContext(userDataDir, opts) has not been implemented yet!"))
153+
k6common.Throw(rt, errors.New("BrowserType.LaunchPersistentContext(userDataDir, opts) has not been implemented yet"))
146154
return nil
147155
}
148156

149157
func (b *BrowserType) Name() string {
150158
return "chromium"
151159
}
160+
161+
// makes an extension wide logger
162+
func makeLogger(ctx context.Context, launchOpts *common.LaunchOptions) (*common.Logger, error) {
163+
var (
164+
k6Logger = k6lib.GetState(ctx).Logger
165+
reCategoryFilter, _ = regexp.Compile(launchOpts.LogCategoryFilter)
166+
logger = common.NewLogger(ctx, k6Logger, launchOpts.Debug, reCategoryFilter)
167+
)
168+
// set the log level from the launch options (usually from a script's options).
169+
if launchOpts.Debug {
170+
_ = logger.SetLevel("debug")
171+
}
172+
if el, ok := os.LookupEnv("XK6_BROWSER_LOG"); ok {
173+
if err := logger.SetLevel(el); err != nil {
174+
return nil, err
175+
}
176+
}
177+
if _, ok := os.LookupEnv("XK6_BROWSER_CALLER"); ok {
178+
logger.ReportCaller()
179+
}
180+
return logger, nil
181+
}

‎common/barrier_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ func TestBarrier(t *testing.T) {
3232
t.Run("should work", func(t *testing.T) {
3333
ctx := context.Background()
3434
timeoutSetings := NewTimeoutSettings(nil)
35-
frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings)
35+
frameManager := NewFrameManager(ctx, nil, nil, timeoutSetings, NewLogger(ctx, NullLogger(), false, nil))
3636
frame := NewFrame(ctx, frameManager, nil, cdp.FrameID("frame_id_0123456789"))
3737

3838
barrier := NewBarrier()

‎common/browser.go

Lines changed: 41 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,6 @@ package common
2323
import (
2424
"context"
2525
"fmt"
26-
"regexp"
2726
"strings"
2827
"sync"
2928
"sync/atomic"
@@ -36,7 +35,6 @@ import (
3635
"github.com/dop251/goja"
3736
"github.com/gorilla/websocket"
3837
"github.com/grafana/xk6-browser/api"
39-
k6lib "go.k6.io/k6/lib"
4038
)
4139

4240
// Ensure Browser implements the EventEmitter and Browser interfaces
@@ -85,9 +83,7 @@ type Browser struct {
8583
}
8684

8785
// NewBrowser creates a new browser
88-
func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *BrowserProcess, launchOpts *LaunchOptions) (*Browser, error) {
89-
state := k6lib.GetState(ctx)
90-
reCategoryFilter, _ := regexp.Compile(launchOpts.LogCategoryFilter)
86+
func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *BrowserProcess, launchOpts *LaunchOptions, logger *Logger) (*Browser, error) {
9187
b := Browser{
9288
BaseEventEmitter: NewBaseEventEmitter(ctx),
9389
ctx: ctx,
@@ -103,7 +99,7 @@ func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *B
10399
pages: make(map[target.ID]*Page),
104100
sessionIDtoTargetIDMu: sync.RWMutex{},
105101
sessionIDtoTargetID: make(map[target.SessionID]target.ID),
106-
logger: NewLogger(ctx, state.Logger, launchOpts.Debug, reCategoryFilter),
102+
logger: logger,
107103
}
108104
if err := b.connect(); err != nil {
109105
return nil, err
@@ -112,6 +108,7 @@ func NewBrowser(ctx context.Context, cancelFn context.CancelFunc, browserProc *B
112108
}
113109

114110
func (b *Browser) connect() error {
111+
b.logger.Debugf("Browser:connect", "wsURL:%v", b.browserProc.WsURL())
115112
var err error
116113
b.conn, err = NewConnection(b.ctx, b.browserProc.WsURL(), b.logger)
117114
if err != nil {
@@ -126,6 +123,7 @@ func (b *Browser) connect() error {
126123
}
127124

128125
func (b *Browser) disposeContext(id cdp.BrowserContextID) error {
126+
b.logger.Debugf("Browser:disposeContext", "bctxid:%v", id)
129127
action := target.DisposeBrowserContext(id)
130128
if err := action.Do(cdp.WithExecutor(b.ctx, b.conn)); err != nil {
131129
return fmt.Errorf("unable to dispose browser context %T: %w", action, err)
@@ -164,10 +162,14 @@ func (b *Browser) initEvents() error {
164162
return
165163
case event := <-chHandler:
166164
if ev, ok := event.data.(*target.EventAttachedToTarget); ok {
165+
b.logger.Debugf("Browser:initEvents:onAttachedToTarget", "sid:%v tid:%v", ev.SessionID, ev.TargetInfo.TargetID)
167166
go b.onAttachedToTarget(ev)
168167
} else if ev, ok := event.data.(*target.EventDetachedFromTarget); ok {
168+
b.logger.Debugf("Browser:initEvents:onDetachedFromTarget", "sid:%v", ev.SessionID)
169169
go b.onDetachedFromTarget(ev)
170170
} else if event.typ == EventConnectionClose {
171+
b.logger.Debugf("Browser:initEvents:EventConnectionClose", "")
172+
171173
b.connMu.Lock()
172174
b.connected = false
173175
b.connMu.Unlock()
@@ -197,31 +199,38 @@ func (b *Browser) initEvents() error {
197199
func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
198200
b.contextsMu.RLock()
199201
var browserCtx *BrowserContext = b.defaultContext
200-
if b, ok := b.contexts[ev.TargetInfo.BrowserContextID]; ok {
201-
browserCtx = b
202+
bctx, ok := b.contexts[ev.TargetInfo.BrowserContextID]
203+
if ok {
204+
browserCtx = bctx
202205
}
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)
203207
b.contextsMu.RUnlock()
204208

205209
// We're not interested in the top-level browser target, other targets or DevTools targets right now.
206210
isDevTools := strings.HasPrefix(ev.TargetInfo.URL, "devtools://devtools")
207211
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)
208213
return
209214
}
210215

211216
if ev.TargetInfo.Type == "background_page" {
212-
p, err := NewPage(b.ctx, b.conn.getSession(ev.SessionID), browserCtx, ev.TargetInfo.TargetID, nil, false)
217+
p, err := NewPage(b.ctx, b.conn.getSession(ev.SessionID), browserCtx, ev.TargetInfo.TargetID, nil, false, b.logger)
213218
if err != nil {
214219
isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected()
215220
if _, ok := err.(*websocket.CloseError); !ok && !isRunning {
216221
// 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",
223+
ev.SessionID, ev.TargetInfo.TargetID, err)
217224
return
218225
}
219226
k6Throw(b.ctx, "cannot create NewPage for background_page event: %w", err)
220227
}
221228
b.pagesMu.Lock()
229+
b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding tid", ev.SessionID, ev.TargetInfo.TargetID)
222230
b.pages[ev.TargetInfo.TargetID] = p
223231
b.pagesMu.Unlock()
224232
b.sessionIDtoTargetIDMu.Lock()
233+
b.logger.Debugf("Browser:onAttachedToTarget:background_page", "sid:%v tid:%v, adding sid", ev.SessionID, ev.TargetInfo.TargetID)
225234
b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
226235
b.sessionIDtoTargetIDMu.Unlock()
227236
} else if ev.TargetInfo.Type == "page" {
@@ -230,20 +239,24 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
230239
if t, ok := b.pages[ev.TargetInfo.OpenerID]; ok {
231240
opener = t
232241
}
242+
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v opener nil:%t", ev.SessionID, ev.TargetInfo.TargetID, opener == nil)
233243
b.pagesMu.RUnlock()
234-
p, err := NewPage(b.ctx, b.conn.getSession(ev.SessionID), browserCtx, ev.TargetInfo.TargetID, opener, true)
244+
p, err := NewPage(b.ctx, b.conn.getSession(ev.SessionID), browserCtx, ev.TargetInfo.TargetID, opener, true, b.logger)
235245
if err != nil {
236246
isRunning := atomic.LoadInt64(&b.state) == BrowserStateOpen && b.IsConnected() //b.conn.isConnected()
237247
if _, ok := err.(*websocket.CloseError); !ok && !isRunning {
238248
// 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)
239250
return
240251
}
241252
k6Throw(b.ctx, "cannot create NewPage for page event: %w", err)
242253
}
243254
b.pagesMu.Lock()
255+
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, adding page as a target", ev.SessionID, ev.TargetInfo.TargetID)
244256
b.pages[ev.TargetInfo.TargetID] = p
245257
b.pagesMu.Unlock()
246258
b.sessionIDtoTargetIDMu.Lock()
259+
b.logger.Debugf("Browser:onAttachedToTarget:page", "sid:%v tid:%v, changing sid to tid", ev.SessionID, ev.TargetInfo.TargetID)
247260
b.sessionIDtoTargetID[ev.SessionID] = ev.TargetInfo.TargetID
248261
b.sessionIDtoTargetIDMu.Unlock()
249262
browserCtx.emit(EventBrowserContextPage, p)
@@ -253,15 +266,18 @@ func (b *Browser) onAttachedToTarget(ev *target.EventAttachedToTarget) {
253266
func (b *Browser) onDetachedFromTarget(ev *target.EventDetachedFromTarget) {
254267
b.sessionIDtoTargetIDMu.RLock()
255268
targetID, ok := b.sessionIDtoTargetID[ev.SessionID]
269+
b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v", ev.SessionID, targetID)
256270
b.sessionIDtoTargetIDMu.RUnlock()
257271
if !ok {
272+
b.logger.Debugf("Browser:onDetachedFromTarget", "sid:%v tid:%v, returns", ev.SessionID, targetID)
258273
// We don't track targets of type "browser", "other" and "devtools", so ignore if we don't recognize target.
259274
return
260275
}
261276

262277
b.pagesMu.Lock()
263278
defer b.pagesMu.Unlock()
264279
if t, ok := b.pages[targetID]; ok {
280+
b.logger.Debugf("Browser:onDetachedFromTarget", "tid:%v, delete page", targetID)
265281
delete(b.pages, targetID)
266282
t.didClose()
267283
}
@@ -276,8 +292,9 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
276292
}
277293

278294
var (
279-
mu sync.RWMutex // protects targetID
280-
targetID target.ID
295+
mu sync.RWMutex // protects targetID
296+
targetID target.ID
297+
localTargetID target.ID // sync free access for logging
281298

282299
err error
283300
)
@@ -286,6 +303,7 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
286303
func(data interface{}) bool {
287304
mu.RLock()
288305
defer mu.RUnlock()
306+
b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, createWaitForEventHandler", targetID, id)
289307
return data.(*Page).targetID == targetID
290308
},
291309
)
@@ -295,15 +313,21 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
295313
action := target.CreateTarget("about:blank").WithBrowserContextID(id)
296314
mu.Lock()
297315
defer mu.Unlock()
316+
localTargetID = targetID
317+
b.logger.Debugf("Browser:newPageInContext", "tid:%v bcid:%v, CreateTarget(blank)", localTargetID, id)
298318
if targetID, err = action.Do(cdp.WithExecutor(b.ctx, b.conn)); err != nil {
299319
errCh <- fmt.Errorf("unable to execute %T: %w", action, err)
300320
}
301321
}()
302322
select {
303323
case <-b.ctx.Done():
324+
b.logger.Debugf("Browser:newPageInContext:<-b.ctx.Done", "tid:%v bcid:%v", localTargetID, id)
304325
case <-time.After(b.launchOpts.Timeout):
305-
case <-ch:
326+
b.logger.Debugf("Browser:newPageInContext:timeout", "tid:%v bcid:%v timeout:%s", localTargetID, id, b.launchOpts.Timeout)
327+
case c := <-ch:
328+
b.logger.Debugf("Browser:newPageInContext:<-ch", "tid:%v bcid:%v, c:%v", localTargetID, id, c)
306329
case err := <-errCh:
330+
b.logger.Debugf("Browser:newPageInContext:<-errCh", "tid:%v bcid:%v, err:%v", localTargetID, id, err)
307331
return nil, err
308332
}
309333
b.pagesMu.RLock()
@@ -313,8 +337,10 @@ func (b *Browser) newPageInContext(id cdp.BrowserContextID) (*Page, error) {
313337

314338
// Close shuts down the browser
315339
func (b *Browser) Close() {
340+
b.logger.Debugf("Browser:Close", "")
316341
if !atomic.CompareAndSwapInt64(&b.state, b.state, BrowserStateClosing) {
317342
// If we're already in a closing state then no need to continue.
343+
b.logger.Debugf("Browser:Close", "already in a closing state")
318344
return
319345
}
320346
b.browserProc.GracefulClose()
@@ -350,6 +376,7 @@ func (b *Browser) IsConnected() bool {
350376
func (b *Browser) NewContext(opts goja.Value) api.BrowserContext {
351377
action := target.CreateBrowserContext().WithDisposeOnDetach(true)
352378
browserContextID, err := action.Do(cdp.WithExecutor(b.ctx, b.conn))
379+
b.logger.Debugf("Browser:NewContext", "browserContextID: %v", browserContextID)
353380
if err != nil {
354381
k6Throw(b.ctx, "unable to execute %T: %w", action, err)
355382
}
@@ -361,6 +388,7 @@ func (b *Browser) NewContext(opts goja.Value) api.BrowserContext {
361388

362389
b.contextsMu.Lock()
363390
defer b.contextsMu.Unlock()
391+
b.logger.Debugf("Browser:NewContext", "NewBrowserContext: %v", browserContextID)
364392
browserCtx := NewBrowserContext(b.ctx, b.conn, b, browserContextID, browserCtxOpts, b.logger)
365393
b.contexts[browserContextID] = browserCtx
366394

0 commit comments

Comments
 (0)