Bug #3761
closedDuplicate/scrambled characters in log message
100%
Description
On a fresh OS X 10.11 virtual machine, I built the latest ndn-cxx and NFD. In one terminal window, I start NFD. In another terminal window I run nfd-status
. Some of the log messages are scrambled like:
472714477623754.79603152.4920 1I2N4F2O :I N[FFOa:c e[TFaabcleeT]a bAlded]e dA dfdaecde fiadc=e2 6i3d =r2e6m3o tree=mfodt:e/=/f3d6: /l/o3c6a ll=oucnailx=:u/n/i/xp:r/i/v/aptrei/vvaatre//rvuanr//nrfudn./snofcdk.
11447722774477663355..997722992233 IINNFFOO:: [[AAuuttooPPrreeffiixxPPrrooppaaggaattoorr]] llooccaall rreeggiissttrraattiioonn oonnllyy ffoorr //llooccaallhhoosstt//nnffdd
Maybe two threads are trying to write the same message to the log stream?
Updated by Alex Afanasyev about 8 years ago
- Priority changed from Normal to High
- Target version set to v0.5
I am confirming the problem on my OSX installation and I have found the offending commit.
The problem started since ndn-cxx:commit:43a7932ed219787fb94c81d2a2ae8d14e268f865 has been merged, which enables logging for ndn-cxx Dispatcher.
What I got so far, boost logging is initialized twice with std::clog destination stream. Once by NFD's logging facility and once by ndn-cxx as soon as there is one user of that facility in the ndn-cxx. Not sure what kind of workaround we can get.
Updated by Alex Afanasyev about 8 years ago
Same appears when using the new logging of nfdc:
✔ 13:16 ~/Devel/ndn/NFD [ master | ✔ ] $ NDN_LOG=CommandParser=TRACE nfdc create udp://spurs.cs.ucla.edu
1473106613.337460 1T4R7A3C1E0:6 6[1Comman3d.P3a3r7s4e6r0] TRfAoCuEn:d comm a[nCdo mcmraenadtPear s
er] found command create
Face creation succeeded: ControlParameters(FaceId: 262, FacePersistency: persistent, )
Updated by Junxiao Shi about 8 years ago
- Category set to Core
The straightforward solution is to use ndn-cxx logging from all NFD components.
My concern is: this bug implies that ndn-cxx logging would conflict with any app that also uses Boost.Log.
So it's better if there's a solution from ndn-cxx side that ensures separate "instances" of Boost.Log are used.
Updated by Alex Afanasyev about 8 years ago
I agree that just redirecting NFD logging to cxx would not solve the problem. It will just hide it from us.
If there was a way to ensure that boost::log::core::get()
has exactly one sink that is directed to std::clog?
Updated by Junxiao Shi about 8 years ago
note-2 indicates that the straightforward solution in note-3 is ineffective.
The problem is that multiple sinks have been added.
Since each ndn::util::Logging
instance guarantees only one sink is added, this means the singleton implementation of Logging::get
is ineffective when ndn-cxx is dynamically linked with NFD.
Updated by Alex Afanasyev about 8 years ago
I actually checked. There is only one instance of Logging
created, so the pattern is working. I just think that the problem is with the underlying boost logger's core.
Updated by Alex Afanasyev about 8 years ago
The ideal way would be for the final application to explicitly define whether to enable logging and where the log should be directed.
For the quick solution, we can add
boost::log::core::get()->remove_all_sinks();
in NFD and ndn-cxx just before boost::log::core::get()->add_sink(m_sink);
call. What do you think?
Updated by Junxiao Shi about 8 years ago
I'm looking at Boost.Log Design Overview.
My proposal is:
- In ndn-cxx source, append a source-specific attribute to each entry.
- In ndn-cxx sink frontend, use sink-specific filtering to only output entries with this attribute.
- Do the same in NFD source and sink frontend.
Benefit: Other applications and libraries that also use Boost.Log can define their own sources and sinks, as long as attribute filters are used in the same fashion.
Updated by Jeff Burke about 8 years ago
- Priority changed from High to Urgent
+1 that I have observed this as well, per earlier email to Junxiao & Alex. Any chance of fix soon?
Updated by Alex Afanasyev about 8 years ago
- Status changed from New to Code review
- % Done changed from 0 to 30
Pushed a temporary fix:
Updated by Junxiao Shi about 8 years ago
Why is remove_all_sinks
needed in both ndn-cxx and NFD?
Can we comment out sink initialization code in NFD, and ensure ndn-cxx's sink initialization is called? It should be called by Dispatcher
used in NFD management.
Updated by Alex Afanasyev about 8 years ago
Does the error exists on Linux? If behavior on Linux is "correct", then removing initialization in NFD would remove all the logs.
Updated by Junxiao Shi about 8 years ago
Follow-up to note-11 note-12:
After deleting Boost.Log backend initialization code, the result on Linux is:
vagrant@m0212:~/NFD$ build/bin/nfd
[2016-09-12 02:10:59.793479] [0x069f8780] [info] 1473646259.793436 INFO: [CsPolicy] setLimit 10
[2016-09-12 02:10:59.793637] [0x069f8780] [info] 1473646259.793623 INFO: [StrategyChoice] setDefaultStrategy /localhost/nfd/strategy/best-route/%FD%04
[2016-09-12 02:10:59.793989] [0x069f8780] [info] 1473646259.793978 INFO: [InternalForwarderTransport] [id=0,local=internal://,remote=internal://] Creating transport
[2016-09-12 02:10:59.794079] [0x069f8780] [info] 1473646259.794072 INFO: [FaceTable] Added face id=1 remote=internal:// local=internal://
[2016-09-12 02:10:59.794914] [0x069f8780] [info] 1473646259.794906 WARNING: [CommandAuthenticator] 'certfile any' is intended for demo purposes only and SHOULD NOT be used in production environments
[2016-09-12 02:10:59.795238] [0x069f8780] [info] 1473646259.795224 INFO: [StrategyChoice] changeStrategy(/ndn/broadcast) from /localhost/nfd/strategy/best-route/%FD%04 to /localhost/nfd/strategy/multicast/%FD%01
[2016-09-12 02:10:59.795313] [0x069f8780] [info] 1473646259.795302 INFO: [StrategyChoice] changeStrategy(/localhost) from /localhost/nfd/strategy/best-route/%FD%04 to /localhost/nfd/strategy/multicast/%FD%01
[2016-09-12 02:10:59.795361] [0x069f8780] [info] 1473646259.795351 INFO: [StrategyChoice] changeStrategy(/localhost/nfd) from /localhost/nfd/strategy/multicast/%FD%01 to /localhost/nfd/strategy/best-route/%FD%04
[2016-09-12 02:10:59.795400] [0x069f8780] [info] 1473646259.795394 INFO: [CsPolicy] setLimit 65536
[2016-09-12 02:10:59.795696] [0x069f8780] [info] 1473646259.795689 FATAL: [NFD] bind: Permission denied
Adding a ndn::util::Logging::setDestination(std::clog)
call in nfd::LoggerFactory
constructor makes the output correct.
I've tested on Ubuntu 14.04 64-bit and OSX 10.11.
If you agree with this solution, assign this issue to me, and I'll upload the Change.
Updated by Alex Afanasyev about 8 years ago
I pushed a revision of the patchset (change in ndn-cxx no longer required). However, I think it is still a temporary solution. NLSR, for example, would have exactly the same problem and would need fix too.
I think note-8 solution sounds more promising in long term.
Updated by Junxiao Shi about 8 years ago
- Assignee set to Alex Afanasyev
- % Done changed from 30 to 100
NLSR would have exactly the same problem and would need fix too.
NLSR uses log4cxx instead of Boost.Log, so it's unaffected.
Applications that use Boost.Log will be affected.
Updated by Junxiao Shi about 8 years ago
- Status changed from Code review to Closed
Updated by Davide Pesavento about 8 years ago
Why was this issue closed? Commit 6459e64f363770d188659f17e037085339201bb3 is just a temporary workaround.
Updated by Junxiao Shi about 8 years ago
I'll create another issue for better solutions.
Updated by Junxiao Shi about 8 years ago
- Blocks Bug #3782: Logging facility conflicts with app using Boost.Log added