Logging issues

[anyuta1166]

Hello. My setup: ejabberd 20.07 with stun 1.0.38. compiled using rebar 2.6.4, Erlang/OTP version 23.1.

In ejabberd.yml I have: loglevel: info

The issue is that I don't see info level messages from the stun/turn library module in logs. I see only notice level ones.

For example, I see

[notice] <0.566.0>@turn:wait_for_allocate/2:194 Creating TURN allocation (lifetime: 600 seconds)
[notice] <0.565.0>@turn:terminate/3:446 Relayed 244 KiB (in 3296 B / 42 packets, out 247058 B / 2370 packets), duration: 47 seconds

but I don't see such messages as "Accepting long-term STUN/TURN authentication" as in previous versions (before switching to new logging API on Erlang/OTP 22+).

I see these messages in logs only if I manually change ?LOG_INFO to ?LOG_NOTICE in the code and recompile the stun library.

rebar debug output shows that erlang version is correctly identified as 23:

DEBUG: Matched required ERTS version: 11.1 -> .*
DEBUG: Matched required OTP release: 23 -> .*
DEBUG: Min OTP version unconfigured
DEBUG: erl_opts [debug_info,debug_info,{i,"include"},{d,'RAND_UNIFORM'}]
DEBUG: Files to compile first: []
DEBUG: Starting 3 compile worker(s)

Also the changelog states that: Add session ID, transport, username, and IP addresses to log output. But I don't see such info. In my example you can see plain "Creating TURN allocation (lifetime: 600 seconds)" without additional info.

[weiss]

The issue is that I don't see info level messages from the stun/turn library module in logs. I see only notice level ones.

Yes, it's complicated. There are two problems:

1. Dealing with two different logging frameworks, and
2. figuring out what amount of log messages ejabberd users might want to see.

For ejabberd, the processone/stun log level is hard-capped at notice level. info level would log many STUN/TURN-specific details, and the assumption is that ejabberd admins will generally not be interested in those just because they configured info or debug logging for ejabberd itself. We could add a separate log_level option for ejabberd_stun listeners, but so far I haven't seen ejabberd admins asking for more detailed STUN/TURN logs, so I figured we'd keep things simple as long as there's no real demand.

I don't see such messages as "Accepting long-term STUN/TURN authentication" as in previous versions

That's a somewhat unrelated change: Rather than logging authentication, we now log TURN relay allocation (and termination) at notice level, as that seemed more useful to me.

Also the changelog states that: Add session ID, transport, username, and IP addresses to log output. But I don't see such info.

This seems like a bug indeed. I'll look into it, thanks.

[anyuta1166]

info level would log many STUN/TURN-specific details, and the assumption is that ejabberd admins will generally not be interested in those just because they configured info or debug logging for ejabberd itself.

Hmmm... By the way, my ejabberd's stun server got DDOSed today and logs were filled with messages like

2020-10-01 14:32:53.061255+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.087834+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.118869+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.124446+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.168903+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.219352+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.223723+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.291429+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.605681+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.637882+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.714483+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.852905+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.901634+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.942458+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]
2020-10-01 14:32:53.982647+03:00 [notice] <0.607.0>@stun:process/3:292 Rejecting request with unknown attribute(s): [3]

Is that intentional that this messages have notice log level and filling logs with useless info?

[weiss]

Is that intentional that this messages have notice log level and filling logs with useless info?

It was intended to log messages that might help while debugging STUN/TURN issues. That includes messages which explain why a request was rejected. I didn't intend to fill your logs with useless info, no.

I tried hard to improve our STUN/TURN logging over the past few weeks. Figuring out what exactly is most useful to admins under different circumstances is not exactly trivial, and I'm open to suggestions for improvements.