Debug logging madness after September update

Help and Support
1

Hi there,

since September update debug logging seems to be activated. Video playback is stuttering and kodi.log is growing and growing (200mb+ 1h). Seems IO is the bottleneck, so I tried to disable logging, but no success.

21:15:57 187.673157 T:1958629936 NOTICE: Starting Kodi (15.2-RC2). Platform: Linux ARM (Thumb) 32-bit
21:15:57 187.673233 T:1958629936 NOTICE: Using Debug Kodi x32 build (version for Raspberry Pi)
21:15:57 187.673340 T:1958629936 NOTICE: Kodi compiled Sep 27 2015 by GCC 4.9.2 for Linux ARM (Thumb) 32-bit version 3.16.7 (200711)
21:15:57 187.673645 T:1958629936 NOTICE: Running on Open Source Media Center 2015.09-1, kernel: Linux ARM 32-bit version 4.2.1-1-osmc

I tried to deactivate logging

  • in advancedsettings.xml:
    21:15:57 187.859390 T:1958629936 NOTICE: Disabled debug logging due to GUI setting. Level -1.
    21:15:57 187.859451 T:1958629936 NOTICE: Log level changed to “LOG_LEVEL_NONE”
    but debug logging is still activated:
    21:37:25 1475.440796 T:1547695136 DEBUG: CMMALRenderer::GetImage - MMAL: image:0x5c3fe9dc source:0 ro:0 flight:0
    21:37:25 1475.441162 T:1547695136 DEBUG: CMMALRenderer::AddProcessor - 0x693a1260 (0x5f76a9d0) 0
    21:37:25 1475.441406 T:1958629936 DEBUG: CMMALRenderer::RenderUpdate - MMAL: clear:0 flags:0 alpha:255 source:1 omvb:0x6936a6a8 mmal:0x5f76b890 mflags:10000004
    …
  • symlinking kodi.log to /dev/null
    after restart/reboot same again

So no success. Any hints how to get rid of the debug messages?

Cheers,
Sebastian

2

So, disabling debug logging the normal way doesn’t work ?

Settings->System->Debugging->Enable debug logging (turn it off)

By the way I leave debug logging on all the time on my test Pi 2 and it does not cause any problems with a Disk IO bottleneck. Unless there is a problem, the debug log is not so verbose as to bog the system down through debug logging…

3

Nope, it was already disabled. I also activated and deativated it.

Perhaps debug logging is activated because it’s a debug build and not a release build?

4

No, it’s not a debug build.

Please use the My OSMC log uploader to upload your debug logs so we can see if there is an issue.

5

Having the exact same issue here. The log file has grown to 764MB in one hour.

6

I’m having the same issue as well. I even disabled logging in the advancedsettings.xml file however it is still logging everything including debug messages.

00:42:32  46.437992 T:1958076976  NOTICE: Disabled debug logging due to GUI setting. Level -1.
00:42:32  46.438042 T:1958076976  NOTICE: Log level changed to "LOG_LEVEL_NONE"
00:42:32  46.441788 T:1958076976  NOTICE: CMediaSourceSettings: loading media sources from special://masterprofile/sources.xml
00:42:32  46.471809 T:1958076976  NOTICE: Loading player core factory settings from special://xbmc/system/playercorefactory.xml.
00:42:32  46.504322 T:1958076976   DEBUG: CPlayerCoreConfig::<ctor>: created player DVDPlayer for core 1
00:42:32  46.504406 T:1958076976   DEBUG: CPlayerCoreConfig::<ctor>: created player oldmplayercore for core 1
00:42:32  46.504463 T:1958076976   DEBUG: CPlayerCoreConfig::<ctor>: created player PAPlayer for core 3
00:42:32  46.504520 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: system rules
00:42:32  46.504578 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: hdhomerun/mms/udp
00:42:32  46.504639 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: lastfm/shout
00:42:32  46.504696 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtmp
00:42:32  46.504753 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtsp
00:42:32  46.504810 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: streams
00:42:32  46.504864 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: aacp/sdp
00:42:32  46.504917 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: mp2
00:42:32  46.504978 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvd
00:42:32  46.505035 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvdimage
00:42:32  46.505089 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: sdp/asf
00:42:32  46.505146 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: nsv
00:42:32  46.505203 T:1958076976   DEBUG: CPlayerSelectionRule::Initialize: creating rule: radio
00:42:32  46.505257 T:1958076976  NOTICE: Loaded playercorefactory configuration
00:42:32  46.509090 T:1958076976  NOTICE: Loading player core factory settings from special://masterprofile/playercorefactory.xml.
00:42:32  46.509312 T:1958076976  NOTICE: special://masterprofile/playercorefactory.xml does not exist. Skipping.
00:42:34  48.391766 T:1958076976    INFO: creating subdirectories
00:42:34  48.391930 T:1958076976    INFO: userdata folder: special://masterprofile/
00:42:34  48.392014 T:1958076976    INFO: recording folder:
00:42:34  48.392082 T:1958076976    INFO: screenshots folder:
7

After September update I confirm this too can see debug messages even debug option is turned off

8

Guys, saying me too without providing a full debug log helps nobody figure out this issue.

A snippet of log a few lines long does NOT help us either.

I appreciate that your log may now be too large to upload so reboot twice in a row to clear both Kodi logs then use the my OSMC log uploader as quickly as possible (before the log grows in size) to upload a full set of debug logs.

9

Here’s my full logs… (rebooted twice)

http://paste.osmc.io/decadipija

10

Hi,

We have identified the cause of excessive debug logging and are building a new version of Kodi to address this.

4 Likes
11

Hi, I updated this morning and for me debug logging is fixed

Full logs http://paste.osmc.io/berewovupa

12

07:31:31 24.328651 T:1957970480 NOTICE: Starting Kodi (15.2-RC2). Platform: Linux ARM (Thumb) 32-bit
07:31:31 24.328722 T:1957970480 NOTICE: Using Release Kodi x32 build (version for Raspberry Pi)

thx, for the rebuild. everthing’s fine now.

13

@DBMandrake
I’m still having this issue on a fresh install and fully updated system.

Log http://paste.osmc.io/itecorawuz

14

According to your log file this is not a debug build like the initial September release accidentally was:

17:00:49   7.181012 T:1957929520  NOTICE: Using Release Kodi x32 build (version for Raspberry Pi)

(It would say Debug Kodi not Release Kodi if this was the case)

So your issue is unrelated to the one discussed in this thread.

Meanwhile the log says that you have debug mode enabled in a custom advancedsettings.xml:

17:00:49   7.613135 T:1957929520  NOTICE: Contents of special://profile/advancedsettings.xml are...
                                            <advancedsettings>
                                              <loglevel hide="false">1</loglevel>
                                              <!--<network>
                                                <buffermode>1</buffermode>
                                            	<cachemembuffersize>157286400</cachemembuffersize>
                                                <readbufferfactor>20</readbufferfactor>
                                             </network>-->
                                            </advancedsettings>
17:00:49   7.613218 T:1957929520  NOTICE: Log level changed to "LOG_LEVEL_DEBUG"

So remove the loglevel option from your advancedsettings file… :wink:

15

Thank you.

So to be clear, this is normal with all this debug info from CMMAL when playing videos?

I always have had enabled debug in my advancedsettings.xml and have never seen this kind of “spam”
Since the last update I have experienced a lot of crashes and sad faces, and it quite hard to find out what is wrong, when a single second of video creates 476 lines in the kodi.log

16

Have you turned on component specific debugging and then enabled logging for video component?
That will generate a log of MMAL messages. Try disabling that.

1 Like
17

Thank you @popcornmix

Apparently component specific debugging and verbose logging for the video component was activated by default, deactivated it and now all is back to normal, and i can begin troubleshooting :smile: