search

RestComm / jain-sip

Disclaimer: This repository is a git-svn mirror of the project found at http://java.net/projects/jsip whose original repository is developed collaboratively by the Advanced Networking Technologies Division at the National Institute of Standards and Technology (NIST) - an agency of the United States Department of Commerce and by a community of individual and enterprise contributors. TeleStax, Inc. will perform some productization work, new features experimentation branches, etc for its TelScale jSIP product that doesn't concern the community from the main repository hence this git repository.
http://www.restcomm.com/
142 stars 151 forks source link

NullPointerException for legacy Logger #86

Closed ooktay closed 2 years ago

ooktay commented 8 years ago

While creating multiple sip stacks concurrently, I get the following exception: java.lang.NullPointerException at gov.nist.core.LogWriter.logError(LogWriter.java:279) at gov.nist.core.CommonLogger.logError(CommonLogger.java:86) at gov.nist.javax.sip.SipStackImpl.createListeningPoint(SipStackImpl.java:1500)

The culprit is this line: https://github.com/RestComm/jain-sip/blob/master/src/gov/nist/javax/sip/SipStackImpl.java#L774

This line updates the static logger field and causes the field to appear null for a short period of time to other threads.

jaimecasero commented 8 years ago

could you provide full stack trace for that NPE?(not sure you included the whole thing)

If the assignment done at https://github.com/RestComm/jain-sip/blob/master/src/gov/nist/javax/sip/SipStackImpl.java#L774 was the cause, would not be the NPE at CommonLogger level, instead of LogWriter as your stacktrace suggests?

Next line at https://github.com/RestComm/jain-sip/blob/master/src/gov/nist/javax/sip/SipStackImpl.java#L775 could potentially reach LogWriter.setStackProperties where logger is initiated at https://github.com/RestComm/jain-sip/blob/master/src/gov/nist/core/LogWriter.java#L306

I also wonder what the stack was trying to log, since the NPE is invoked during logError logic. Any hints on that?. It may be we are hiding an actual excepetion that the stack was trying to log. Apparently the original exception is generated from https://github.com/RestComm/jain-sip/blob/master/src/gov/nist/javax/sip/SipStackImpl.java#L1499 . Are you using "gov.nist.javax.sip.SIP_EVENT_INTERCEPTOR" property? If yes, could you check what is happening inside the "init" method implementation?.

Since this seems to be a bootstraping issue, I wonder how strong is the requirement to create those stacks concurrently?....

ooktay commented 8 years ago

The rest of the stack trace is my code trying to open a port, so I can't post it. This exception occurs intermittently in a automated testing application which creates separate sip stacks for each call leg. The app has to run tests concurrently to reduce testing time. So this is not a bootstrapping issue. I had found that this exception occurred when the app assigns the same port to 2 stacks which should fail the test case. However, this exception hid the actual fail reason. Actually, I have switched to log4j which took care of the exception, but there may be other applications who are still using legacy logger. Here is the race condition: LogWriter.logger is initialized in setStackProperties() which is called from SipStackImpl constructor which leaves LogWriter.logger null for a short period after LogWritter instance is assigned to CommonLogger.legacyLogger. (Hmm, it's not the CommonLogger.legacyLogger, but the CommonLogger.legacyLogger.logger) So, putting SipStackImpl.java#L775 above #L774 would solve the issue.

Other thoughts:

jaimecasero commented 8 years ago

Well, if this behavior happens during stack initialization, I would still use bootstrapping as category, in contrast to normal/intialized state where traffic is actually handled. But that was just a category to clarify about the issue, let's focus on the actual issue...

I tend to agree with you on proposed change, so setStackProperties would be called before assigning to "legacyLogger". Since you came out with this suggestion, and you have the environment to test, would you like to contribute to the project with that patch?.

I understand that using log4j changed behavior, so you no longer have that NPE causing noise in your test sutie,right?

ooktay commented 8 years ago

I think I can take back log4j change and test the change next week.

jaimecasero commented 8 years ago

That is greatly appreciated. Thank you very much.

Feel free to create your own fork, and then pull request into this one. Looking forward for your contribution. This link explains contributions workflow http://telestax.com/wp-content/uploads/2016/04/TeleStaxOpenSourcePlaybook.pdf, in case you have any question....

I will look into having you in our acknowledgements page http://telestax.com/acknowledgements/ ( just if you like of course...)