Scallion logging format error

[robgjansen]

On tor-0.2.4.10-alpha, Scallion output is like:

[notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 5/5, and can only build 020274120f likely paths. (We have 05001111756f guards bw, 1005016602000f midpoint bw, and 013634243140f exit bw.)

It should be like:

[notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 96/3458, and can only build 0% of likely paths. (We have 3% of guards bw, 2% of midpoint bw, and 2% of exit bw.)

[kloesing]

I just tried the fix, and it looks like not all log lines end with \n, but some end with \0:

0000160: 5f63 625d 2057 6520 6861 7665 2065 6e6f  _cb] We have eno
0000170: 7567 6820 6465 7363 7269 7074 6f72 733a  ugh descriptors:
0000180: 2077 6520 6861 7665 2035 2f35 2c20 616e   we have 5/5, an
0000190: 6420 6361 6e20 6275 696c 6420 3130 3025  d can build 100%
00001a0: 206f 6620 6c69 6b65 6c79 2070 6174 6873   of likely paths
00001b0: 2e20 2857 6520 6861 7665 2031 3030 2520  . (We have 100%
00001c0: 6f66 2067 7561 7264 7320 6277 2c20 3130  of guards bw, 10
00001d0: 3025 206f 6620 6d69 6470 6f69 6e74 2062  0% of midpoint b
00001e0: 772c 2061 6e64 2031 3030 2520 6f66 2065  w, and 100% of e
00001f0: 7869 7420 6277 2e29 0a4a 616e 2030 3120  xit bw.).Jan 01
                             ^^ \n
0000200: 3030 3a30 353a 3031 2e30 3030 205b 6e6f  00:05:01.000 [no
0000210: 7469 6365 5d20 5765 2068 6176 6520 656e  tice] We have en
0000220: 6f75 6768 2064 6573 6372 6970 746f 7273  ough descriptors
0000230: 3a20 7765 2068 6176 6520 352f 352c 2061  : we have 5/5, a
0000240: 6e64 2063 616e 2062 7569 6c64 2031 3030  nd can build 100
0000250: 2520 6f66 206c 696b 656c 7920 7061 7468  % of likely path
0000260: 732e 2028 5765 2068 6176 6520 3130 3025  s. (We have 100%
0000270: 206f 6620 6775 6172 6473 2062 772c 2031   of guards bw, 1
0000280: 3030 2520 6f66 206d 6964 706f 696e 7420  00% of midpoint
0000290: 6277 2c20 616e 6420 3130 3025 206f 6620  bw, and 100% of
00002a0: 6578 6974 2062 772e 2900 303a 303a 353a  exit bw.).0:0:5:
                               ^^ \0

[robgjansen]

@kloesing Does the \0 cause problems in g_strchomp()? Or is the issue that we are now adding newlines when Tor would not have? If the latter, wasn't that already occurring before this fix?

[kloesing]

The example data above comes from data/scallion.log. We're writing \0 when we should write tor's \n.

[robgjansen]

@kloesing Sorry, I'm still confused. Is the first part of your comment printed with Tor, and the second with Scallion? How can I reproduce this?

With shadow master at commit 34e41c5, my log file looks like this:

[rob@sol minimal]$ cat data/scallion.log | grep "likely paths"
0:0:2:388192 [thread-0] 0:7:6:946175361 [tor-message] [exit2-60.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/5, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 0% of exit bw.)
0:0:2:390330 [thread-0] 0:7:7:269197181 [tor-message] [exit1-59.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/5, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 0% of exit bw.)
0:0:2:391395 [thread-0] 0:7:7:362330314 [tor-message] [exit2-60.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 4/5, and can only build 30% of likely paths. (We have 75% of guards bw, 80% of midpoint bw, and 50% of exit bw.)
0:0:2:392433 [thread-0] 0:7:7:589134509 [tor-message] [relay1-57.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/5, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 0% of exit bw.)
0:0:2:393286 [thread-0] 0:7:7:636170793 [tor-message] [relay2-58.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/5, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 0% of exit bw.)
0:0:2:394711 [thread-0] 0:7:7:915321511 [tor-message] [exit1-59.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 4/5, and can only build 30% of likely paths. (We have 75% of guards bw, 80% of midpoint bw, and 50% of exit bw.)
0:0:2:397021 [thread-0] 0:7:8:344277531 [tor-message] [relay2-58.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 4/5, and can only build 30% of likely paths. (We have 75% of guards bw, 80% of midpoint bw, and 50% of exit bw.)
0:0:2:397677 [thread-0] 0:7:8:472217058 [tor-message] [relay1-57.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 4/5, and can only build 30% of likely paths. (We have 75% of guards bw, 80% of midpoint bw, and 50% of exit bw.)
0:0:3:703452 [thread-0] 0:15:2:164313585 [tor-message] [fileclient-56.1.0.0] [scalliontor_logmsg_cb] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 0/5, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 0% of exit bw.)

The newlines seem to be correctly printed in my minimal test case...

[kloesing]

Here's what I did to reproduce the problem:

sudo apt-get update
sudo apt-get upgrade
wget http://llvm.org/releases/3.2/llvm-3.2.src.tar.gz
wget http://llvm.org/releases/3.2/clang-3.2.src.tar.gz
tar xaf llvm-3.2.src.tar.gz
tar xaf clang-3.2.src.tar.gz
cp -R clang-3.2.src llvm-3.2.src/tools/clang
cd llvm-3.2.src/
mkdir build
cd build/
cmake -DCMAKE_INSTALL_PREFIX=/home/ubuntu/.local ../.
make -j2
make install
export PATH=~/.local/bin/:$PATH
cd ../../
which clang # result: /home/ubuntu/.local/bin//clang
wget http://www.cmake.org/files/v2.8/cmake-2.8.10.2.tar.gz
tar xf cmake-2.8.10.2.tar.gz 
cd cmake-2.8.10.2/
./configure
make
cd ../
export PATH=~/cmake-2.8.10.2/bin:$PATH
git clone https://git.torproject.org/tor.git
git clone https://github.com/shadow/shadow.git
cd shadow/
./setup dependencies
./setup build --tor-prefix /home/ubuntu/tor/
./setup install
export PATH=~/.shadow/bin/:$PATH
cd resource/examples/scallion/
tar xf minimal.tar.xz
cd minimal/
scallion

When I try to grep the resulting data/scallion.log, grep tells me: Binary file data/scallion.log matches

I uploaded the scallion.log file here: https://people.torproject.org/~karsten/volatile/scallion-2013-05-23-issue128.log.gz

[robgjansen]

Scallion used to intercept Tor's logv function to redirect it through Shadow's logging facilities. Since commit 78af9f7, Scallion instead registers a log callback with Tor. I found that Scallion is also now modifying Tor's log msg in place, meaning any log method that happens after our new callback has an unexpected modified msg as input. We should fix that.

Also, commit 78af9f7 logs Tor log messages at the same level as shadow, meaning that your torrc files should no longer have a Log notice stdout or similar line in it (you can just delete them if using Shadow master). Otherwise, you'll additionally log messages at that level from all nodes into data/scallion.log. If we want to enable each Tor node to specify a log level independent of Shadow's log level, we should create a new issue.

I do need to update the included examples in the resource/examples/scallion directory to remove the Log notice stdout line in the torrcs by default. I'll do that as part of this issue. #112 and #127 also are awaiting XML updates in order to be completed.

[kloesing]

Upgrading to latest Shadow master (fc36dfb) and taking out Log * stdout lines from torrc files fixed the problem for me. Thanks!