804371 - NetLog - Implement event logging for Necko

Status: RESOLVED INCOMPLETE

(Core :: Networking, defect, P5)

Description

[Valentin Gosu [:valentin] (he/him)]

This is not meant to replace NSPR logging, but to complement it.
We need something similar to Chrome's net-internals event logging, which would allow us to get detailed logs regarding networking activity and events.

Comment 1

[Valentin Gosu [:valentin] (he/him)]

Attachment: NetLog v0.1

Comment 2

[Jason Duell]

Comment on attachment 674975 [details] [diff] [review]
NetLog v0.1

Review of attachment 674975 [details] [diff] [review]:
-----------------------------------------------------------------

Design questions:

This is so that logging and events can be sent from either the child/parent, but the observers will only live on the parent, right? 

Will your observers live on a separate thread than the main thread?  I assume this is the reason you are duplicating all this code from nsObserverService: if your observer were on the main thread you could just use the existing nsIObserverService.

I'm still thinking about whether it's OK to just cut-and-paste nsObserverService into a new class, or whether we should try to make the existing nsObserverService code flexible enough to handle non-main thread notification, or split some of the code into a base class, or something else.  Meanwhile it would be good to know your design needs.

Minor comments below.

::: netwerk/base/src/NetLog.cpp
@@ +15,5 @@
> +NetObserverService NetLog::serv;
> +bool NetLog::active = false;
> +nsIThread * NetLog::thread = nullptr;
> +
> +inline bool isParentPorcess()

Typo, and capitalize function names in C++ (as opposed to JS): so IsParentProcess.   But IsNeckoChild() in NeckoCommon.h already provides what you need here--use that instead.

@@ +90,5 @@
> +NetLog::AddObserver(nsIObserver * anObserver, const char * aTopic,
> +                    const bool ownsWeak)
> +{
> +    nsresult rv;
> +    rv = serv.AddObserver(anObserver, aTopic, ownsWeak);

It seems you're going to need mutex locking either in this function or in AddObserver.  Same for code that removes observers, and code that notifies them.  Basically all uses of the observer list will need a lock.

@@ +121,5 @@
> +NetLog::DispatchNotification(const char * aTopic, const char * format, va_list args)
> +{
> +    char buffer[MESSAGE_SIZE];
> +
> +    vsnprintf(buffer, MESSAGE_SIZE - 1, format, args);

vsnprintf writes 'up to size bytes, including the terminating null", so seems like you don't need -1 here?

@@ +126,5 @@
> +    nsCOMPtr<nsIRunnable> event = new NetLogEvent(nullptr, aTopic, buffer);
> +    if (isParentPorcess() && thread)
> +        thread->Dispatch(event, NS_DISPATCH_NORMAL);
> +    else
> +        NS_DispatchToMainThread(event, NS_DISPATCH_NORMAL);

Hmm, are you sure notifying observers on a different thread (main) then they expect if !thread is going to work?   More likely it's easier to just NS_RUNTIMEABORT if you can't create a thread (if we're in a state where threads can't be created we're in fatal trouble already).

@@ +148,5 @@
> +bool
> +NetLog::Event(const char * aTopic, const char * aMessage, ...)
> +{
> +    if (!active)
> +        return false;

Instead of having Start/Stop methods, it's probably better to just lazily init the pointer to your observerService the first time it's used.

ah, and the reason we probably want this to be an XPCOM service is because then XPCOM will handle calling Shutdown at the right time, so you don't need to figure out when Stop should be called.  I don't know all the steps to making a new XPCOM service--we can ask someone if that's what we wind up doing here. (and/or you can try to figure it out from existing services like nsHttpHandler).

::: netwerk/base/src/NetLog.h
@@ +4,5 @@
> +
> +#ifndef NetLog__
> +#define NetLog__
> +
> +#include "nsObserverService.h"

Looks like you can replace #include with just a forward declaration of

  class nsIObserver;

Not a big deal--we're sort of trying to keep compilation time down by not including things when unneeded.

@@ +6,5 @@
> +#define NetLog__
> +
> +#include "nsObserverService.h"
> +#include "nsString.h"
> +#include "mozilla/Mutex.h"

Need Mutex.h here?  Put only in .cpp file if you don't need it in .h file.  But you're probably going to need to declare a mutex to protect lists of observers, since I think you're planning to add them from various threads and access them for notification on another thread.

@@ +10,5 @@
> +#include "mozilla/Mutex.h"
> +#include "nsIThread.h"
> +
> +#define NL_HOSTRESOLVER "hostresolver-event"
> +#define NL_SOCKET       "socket-event"

I don't see these used anywhere in patch.  Get rid of them?  OTOH if you're planning to use these in code once you start plugging in netlog, then it might actually be nice to keep event names all in a central place like this.

@@ +18,5 @@
> +class NetLog
> +{
> +friend class NetLogEvent;
> +
> +public:    

trailing whitespace after public

@@ +28,5 @@
> +    static bool Log(const char *, ...);
> +    static bool Event(const char *, const char *, ...);
> +
> +private:
> +    

super-nit:  get rid of whitespace in empty line :)

@@ +32,5 @@
> +    
> +    static void DispatchNotification(const char *, const char *, va_list);
> +    static bool NotifyObservers(nsISupports *, const char *, const PRUnichar *);
> +
> +    static NetObserverService serv;

You can't have static XPCOM objects.  You need to instantiate this at runtime, i.e. a pointer that you allocate on first use, etc.  Often this is by making your class an XPCOM service and having it get initialized on first use.  Not sure if we need that here, but definitely can't be static.

@@ +34,5 @@
> +    static bool NotifyObservers(nsISupports *, const char *, const PRUnichar *);
> +
> +    static NetObserverService serv;
> +    static bool active;
> +    static nsIThread * thread;

use mStatic/mThread.  Always 'm' for member variables.

::: netwerk/ipc/NeckoChild.cpp
@@ +173,5 @@
> +{
> +  if (status)
> +    NetLog::Start();
> +  else
> +    NetLog::Stop();

use braces for if..else

Comment 3

[Valentin Gosu [:valentin] (he/him)]

(In reply to Jason Duell (:jduell) from comment #2)
> Comment on attachment 674975 [details] [diff] [review]
> NetLog v0.1
> 
> Review of attachment 674975 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Design questions:
> 
> This is so that logging and events can be sent from either the child/parent,
> but the observers will only live on the parent, right? 
> 

Right!

> Will your observers live on a separate thread than the main thread?  I
> assume this is the reason you are duplicating all this code from
> nsObserverService: if your observer were on the main thread you could just
> use the existing nsIObserverService.
>

Observers will probably live on the main thread. The problem with nsObserverService is that it only allows for _Notifications_ to be sent from the main thread.
 
> I'm still thinking about whether it's OK to just cut-and-paste
> nsObserverService into a new class, or whether we should try to make the
> existing nsObserverService code flexible enough to handle non-main thread
> notification, or split some of the code into a base class, or something
> else.  Meanwhile it would be good to know your design needs.
> 

My thinking was that it's supposed to be used from the main thread for a reason, so I'm reluctant about changing it.

> Minor comments below.
> 
> ::: netwerk/base/src/NetLog.cpp
> @@ +15,5 @@
> > +NetObserverService NetLog::serv;
> > +bool NetLog::active = false;
> > +nsIThread * NetLog::thread = nullptr;
> > +
> > +inline bool isParentPorcess()
> 
> Typo, and capitalize function names in C++ (as opposed to JS): so
> IsParentProcess.   But IsNeckoChild() in NeckoCommon.h already provides what
> you need here--use that instead.
> 
> @@ +90,5 @@
> > +NetLog::AddObserver(nsIObserver * anObserver, const char * aTopic,
> > +                    const bool ownsWeak)
> > +{
> > +    nsresult rv;
> > +    rv = serv.AddObserver(anObserver, aTopic, ownsWeak);
> 
> It seems you're going to need mutex locking either in this function or in
> AddObserver.  Same for code that removes observers, and code that notifies
> them.  Basically all uses of the observer list will need a lock.
> 

Unfortunatelly, since it's a static class, the mozilla::Mutex will leak (because static objects are destroyed after the leak checks). But I think there are locking mechanisms available, right? 

> @@ +121,5 @@
> > +NetLog::DispatchNotification(const char * aTopic, const char * format, va_list args)
> > +{
> > +    char buffer[MESSAGE_SIZE];
> > +
> > +    vsnprintf(buffer, MESSAGE_SIZE - 1, format, args);
> 
> vsnprintf writes 'up to size bytes, including the terminating null", so
> seems like you don't need -1 here?
> 

Right!

> @@ +126,5 @@
> > +    nsCOMPtr<nsIRunnable> event = new NetLogEvent(nullptr, aTopic, buffer);
> > +    if (isParentPorcess() && thread)
> > +        thread->Dispatch(event, NS_DISPATCH_NORMAL);
> > +    else
> > +        NS_DispatchToMainThread(event, NS_DISPATCH_NORMAL);
> 
> Hmm, are you sure notifying observers on a different thread (main) then they
> expect if !thread is going to work?   More likely it's easier to just
> NS_RUNTIMEABORT if you can't create a thread (if we're in a state where
> threads can't be created we're in fatal trouble already).
> 

The thread check in the condition was being overcautious. Actually, it sends the event to the logging thread if it's in the parent process, or the main thread if it is in the child process - from where it can send to the parent.

> @@ +148,5 @@
> > +bool
> > +NetLog::Event(const char * aTopic, const char * aMessage, ...)
> > +{
> > +    if (!active)
> > +        return false;
> 
> Instead of having Start/Stop methods, it's probably better to just lazily
> init the pointer to your observerService the first time it's used.
> 
> ah, and the reason we probably want this to be an XPCOM service is because
> then XPCOM will handle calling Shutdown at the right time, so you don't need
> to figure out when Stop should be called.  I don't know all the steps to
> making a new XPCOM service--we can ask someone if that's what we wind up
> doing here. (and/or you can try to figure it out from existing services like
> nsHttpHandler).

I've created an XPCOM service

> 
> ::: netwerk/base/src/NetLog.h
> @@ +4,5 @@
> > +
> > +#ifndef NetLog__
> > +#define NetLog__
> > +
> > +#include "nsObserverService.h"
> 
> Looks like you can replace #include with just a forward declaration of
> 
>   class nsIObserver;
> 
> Not a big deal--we're sort of trying to keep compilation time down by not
> including things when unneeded.
> 
> @@ +6,5 @@
> > +#define NetLog__
> > +
> > +#include "nsObserverService.h"
> > +#include "nsString.h"
> > +#include "mozilla/Mutex.h"
> 
> Need Mutex.h here?  Put only in .cpp file if you don't need it in .h file. 
> But you're probably going to need to declare a mutex to protect lists of
> observers, since I think you're planning to add them from various threads
> and access them for notification on another thread.
> 
> @@ +10,5 @@
> > +#include "mozilla/Mutex.h"
> > +#include "nsIThread.h"
> > +
> > +#define NL_HOSTRESOLVER "hostresolver-event"
> > +#define NL_SOCKET       "socket-event"
> 
> I don't see these used anywhere in patch.  Get rid of them?  OTOH if you're
> planning to use these in code once you start plugging in netlog, then it
> might actually be nice to keep event names all in a central place like this.
> 

You're right, for now they're not needed. I tried a few scenarios with events, and left them in accidentally.

> @@ +18,5 @@
> > +class NetLog
> > +{
> > +friend class NetLogEvent;
> > +
> > +public:    
> 
> trailing whitespace after public
> 
> @@ +28,5 @@
> > +    static bool Log(const char *, ...);
> > +    static bool Event(const char *, const char *, ...);
> > +
> > +private:
> > +    
> 
> super-nit:  get rid of whitespace in empty line :)
> 
> @@ +32,5 @@
> > +    
> > +    static void DispatchNotification(const char *, const char *, va_list);
> > +    static bool NotifyObservers(nsISupports *, const char *, const PRUnichar *);
> > +
> > +    static NetObserverService serv;
> 
> You can't have static XPCOM objects.  You need to instantiate this at
> runtime, i.e. a pointer that you allocate on first use, etc.  Often this is
> by making your class an XPCOM service and having it get initialized on first
> use.  Not sure if we need that here, but definitely can't be static.
> 

Thanks! I'll do that.

Comment 4

[Valentin Gosu [:valentin] (he/him)]

@Jason

How do I get hold of all the parents in order to notify the children logging has started?

From what I could find, one way would be the following:

if (isParentPorcess()) {
     nsTArray<ContentParent*> parents;
     ContentParent::GetAll(parents);
     for (uint32_t i = 0; i < parents.Length(); i++)
         parents[i]->SendNetLogStarted(false);
}

However, I don't know if that's right, and also that requires including "ContentParent.h" which is in another modules.

Comment 5

[Jason Duell]

> Observers will probably live on the main thread. 

That's OK as long as they don't do anything blocking (like I/O). Is that true?

> The problem with 
> nsObserverService is that it only allows for _Notifications_ to be sent
> from the main thread.
 
That's fine.  If your observers can all live on the main thread, just have your service's Init() method get a pointer to nsIObserverService, and all your class Event/Log functions need to do is either 1) just call mObserverService->NotifyObservers directly if the Event/Log call is made on the main thread, or 2) send a Runnable event to the main thread and call NotifyObservers there.  So you don't need to copy/paste all the nsObserverService code--it will work fine for you.  You won't even need a mutex or keep your own observer list.  You're really just providing a way do dispatch NotifyObserver() calls from the child and from off-main threads.

But make sure your observers can live on the main thread!  If they block we'll need a very different architecture here.  (One that supports off-main thread delivery).

> How do I get hold of all the parents in order to notify the children logging
> has started?

You don't!  Instead you'll make sure that the logging service gets initialized the first time anyone tries to use it.  See for example nsHttpHandler::GetCookieService:

  http://mxr.mozilla.org/mozilla-central/source/netwerk/protocol/http/nsHttpHandler.cpp#429

Comment 6

[Valentin Gosu [:valentin] (he/him)]

(In reply to Jason Duell (:jduell) from comment #5)
> > Observers will probably live on the main thread. 
> 
> That's OK as long as they don't do anything blocking (like I/O). Is that
> true?
> 

There is no reason why it would do blocking calls. The dashboard will probably be the only observer, so if it would eventually dump the logs to a file, it definitely won't do it on the main thread.

> 
> > How do I get hold of all the parents in order to notify the children logging
> > has started?
> 
> You don't!  Instead you'll make sure that the logging service gets
> initialized the first time anyone tries to use it.  See for example
> nsHttpHandler::GetCookieService:
> 

I opted for this design, so there would be no overhead when logging is not active. If the child processes don't know that logging is disabled, they would keep posting a lot of stuff to the main thread - don't know if that is an issue for child processes. Would it affect performance in the parent process? An event for each log message, would mean a lot of events posted to the main thread.

Comment 7

[Jason Duell]

To disable/enable logging, I'd use a file-scope boolean somewhere that Log()/Event() can check and return without doing anything (no nsIObserver firing). In that case calling Event/Log won't even instantiate the logging service until something turns logging on.  There would only be the function call overhead of Event/Log (which would be very cheap if you can make them inline, or at least make the part that checks the bool inline)

Comment 8

[Honza Bambas (:mayhemer)]

Comment on attachment 674975 [details] [diff] [review]
NetLog v0.1

Review of attachment 674975 [details] [diff] [review]:
-----------------------------------------------------------------

What exactly is a purpose of this class?  Why do we need it?

::: netwerk/base/src/NetLog.cpp
@@ +8,5 @@
> +#include "nsXULAppAPI.h" 
> +#include "mozilla/net/NeckoChild.h"
> +#include "mozilla/net/NeckoParent.h"
> +
> +#define MESSAGE_SIZE 256

Too few I think, make it at least 512 or 1024.

@@ +126,5 @@
> +    nsCOMPtr<nsIRunnable> event = new NetLogEvent(nullptr, aTopic, buffer);
> +    if (isParentPorcess() && thread)
> +        thread->Dispatch(event, NS_DISPATCH_NORMAL);
> +    else
> +        NS_DispatchToMainThread(event, NS_DISPATCH_NORMAL);

I think you can just SendNetLog when you are on child, no?

@@ +133,5 @@
> +bool
> +NetLog::Log(const char * aMessage, ...)
> +{
> +    if (!active)
> +        return false;

return true;

@@ +148,5 @@
> +bool
> +NetLog::Event(const char * aTopic, const char * aMessage, ...)
> +{
> +    if (!active)
> +        return false;

return true;

::: netwerk/base/src/NetLog.h
@@ +14,5 @@
> +#define NL_SOCKET       "socket-event"
> +
> +class NetObserverService;
> +
> +class NetLog

In general, make this a namespace (mozilla::net::Log) and the methods just functions in this namespace.

On the other hand, why this such general scope service should be limited to network only?  Do you plan to add something really just network specific here?

For variables use static and "s" prefix.

Same applies to the NetLogUtils file.

@@ +25,5 @@
> +
> +    static bool AddObserver(nsIObserver *, const char *, const bool);
> +    static bool RemoveObserver(nsIObserver *, const char *);
> +    static bool Log(const char *, ...);
> +    static bool Event(const char *, const char *, ...);

Comments please.

Comment 9

[Valentin Gosu [:valentin] (he/him)]

Sorry for the long pause.

(In reply to Honza Bambas (:mayhemer) from comment #8)
> Comment on attachment 674975 [details] [diff] [review]
> NetLog v0.1
> 
> Review of attachment 674975 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> What exactly is a purpose of this class?  Why do we need it?
> 

We need a logging system that can be enabled at will.
Also, it needs to be very lightweight. That's why I used another thread to dispatch the messages to the handler.
 
> @@ +126,5 @@
> > +    nsCOMPtr<nsIRunnable> event = new NetLogEvent(nullptr, aTopic, buffer);
> > +    if (isParentPorcess() && thread)
> > +        thread->Dispatch(event, NS_DISPATCH_NORMAL);
> > +    else
> > +        NS_DispatchToMainThread(event, NS_DISPATCH_NORMAL);
> 
> I think you can just SendNetLog when you are on child, no?
> 

Only if you are on the main thread, from what Jason tells me. So I sent it to the main thread, which calls SendNetLog.


> ::: netwerk/base/src/NetLog.h
> @@ +14,5 @@
> > +#define NL_SOCKET       "socket-event"
> > +
> > +class NetObserverService;
> > +
> > +class NetLog
> 
> In general, make this a namespace (mozilla::net::Log) and the methods just
> functions in this namespace.
> 
> On the other hand, why this such general scope service should be limited to
> network only?  Do you plan to add something really just network specific
> here?
>

For the time being we only need this for networking, to be used in the Networking Dashboard. Maybe in the future it could be extended to other modules. However, I think the mozilla::net::Log namespace is appropriate for the intended usage.

Comment 10

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 11

[Valentin Gosu [:valentin] (he/him)]

We have LazyLogModules now.