Project

General

Profile

Actions

Bug #3761

closed

Duplicate/scrambled characters in log message

Added by Anonymous about 8 years ago. Updated about 8 years ago.

Status:
Closed
Priority:
Urgent
Category:
Core
Target version:
Start date:
09/01/2016
Due date:
% Done:

100%

Estimated time:

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?


Related issues 1 (0 open1 closed)

Blocks ndn-cxx - Bug #3782: Logging facility conflicts with app using Boost.LogClosedAlex Afanasyev

Actions
Actions #1

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.

Actions #2

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, )
Actions #3

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.

Actions #4

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?

Actions #5

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.

Actions #6

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.

Actions #7

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?

Actions #8

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.

Actions #9

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?

Actions #10

Updated by Alex Afanasyev about 8 years ago

  • Status changed from New to Code review
  • % Done changed from 0 to 30
Actions #11

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.

Actions #12

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.

Actions #13

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.

Actions #14

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.

Actions #15

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.

Actions #16

Updated by Junxiao Shi about 8 years ago

  • Status changed from Code review to Closed
Actions #17

Updated by Davide Pesavento about 8 years ago

Why was this issue closed? Commit 6459e64f363770d188659f17e037085339201bb3 is just a temporary workaround.

Actions #18

Updated by Junxiao Shi about 8 years ago

I'll create another issue for better solutions.

Actions #19

Updated by Junxiao Shi about 8 years ago

  • Blocks Bug #3782: Logging facility conflicts with app using Boost.Log added
Actions

Also available in: Atom PDF