Controller logging categories (with --controllerDebug support) #4523

Holzhaus · 2021-11-15T22:55:19Z

This is the abandoned PR #4522 with support for the --controllerDebug flag added.

Swiftb0y

Thank you very much for spending the time to make this mergeable.

src/test/controller_mapping_validation_test.cpp

src/util/cmdlineargs.cpp

daschuer · 2021-11-16T08:01:19Z

Thank you very much for picking this up.

Unfortunately my log file is now spammed with:

Debug [Controller] Starting one-shot timer: 560
Debug [Controller] Starting one-shot timer: 561
Debug [Controller] Starting one-shot timer: 562
Debug [Controller] Starting one-shot timer: 563
Debug [Controller] Starting one-shot timer: 564
Debug [Controller] Starting one-shot timer: 565
Debug [Controller] Starting one-shot timer: 566
Debug [Controller] Starting one-shot timer: 567
Debug [Controller] Starting one-shot timer: 568
Debug [Controller] Starting one-shot timer: 569
Debug [Controller] Starting one-shot timer: 570
Debug [Controller] Starting one-shot timer: 571
Debug [Controller] Starting one-shot timer: 572
Debug [Controller] Starting one-shot timer: 573
Debug [Controller] Starting one-shot timer: 574
Debug [Controller] Starting one-shot timer: 575
Debug [Controller] Starting one-shot timer: 576
Debug [Controller] Starting one-shot timer: 577
Debug [Controller] Starting one-shot timer: 578
Debug [Controller] Starting one-shot timer: 579
Debug [Controller] Starting one-shot timer: 580
Debug [Controller] Starting one-shot timer: 581
Debug [Controller] Starting one-shot timer: 582
Debug [Controller] Starting one-shot timer: 583
Debug [Controller] Starting one-shot timer: 584
Debug [Controller] Starting one-shot timer: 585
Debug [Controller] Starting one-shot timer: 586
Debug [Controller] Starting one-shot timer: 587
Debug [Controller] Starting one-shot timer: 588
Debug [Controller] Starting one-shot timer: 589
Debug [Controller] Starting one-shot timer: 590
Debug [Controller] Starting one-shot timer: 591
Debug [Controller] Starting one-shot timer: 592
Debug [Controller] Starting one-shot timer: 593
Debug [Controller] Starting one-shot timer: 594
Debug [Controller] Starting one-shot timer: 595
Debug [Controller] Starting one-shot timer: 596
Debug [Controller] Starting one-shot timer: 597
Debug [Controller] Starting one-shot timer: 598
Debug [Controller] Starting one-shot timer: 599
Debug [Controller] Starting one-shot timer: 600
Debug [Controller] Starting one-shot timer: 601
Debug [Controller] Starting one-shot timer: 602
Debug [Controller] Starting one-shot timer: 603
Debug [Controller] Starting one-shot timer: 604
Debug [Controller] Starting one-shot timer: 605
Debug [Controller] Starting one-shot timer: 606
Debug [Controller] Starting one-shot timer: 607
Debug [Controller] Starting one-shot timer: 608
Debug [Controller] Starting one-shot timer: 609
Debug [Controller] Starting one-shot timer: 610
Debug [Controller] Starting one-shot timer: 611
Debug [Controller] Starting one-shot timer: 612
Debug [Controller] Starting one-shot timer: 613
Debug [Controller] Starting one-shot timer: 614
Debug [Controller] Starting one-shot timer: 615
Debug [Controller] Starting one-shot timer: 616
Debug [Controller] Starting one-shot timer: 617
Debug [Controller] Starting one-shot timer: 618
Debug [Controller] Starting one-shot timer: 619
Debug [Controller] Starting one-shot timer: 620
Debug [Controller] Starting one-shot timer: 621
Debug [Controller] Starting one-shot timer: 622
Debug [Controller] Starting one-shot timer: 623
Debug [Controller] Starting one-shot timer: 624
Debug [Controller] Starting one-shot timer: 625
Debug [Controller] Killing timer: 4
Debug [Controller] Killing timer: 11
Debug [Controller] Killing timer: 57
Debug [Controller] Killing timer: 58
Debug [Controller] Killing timer: 60
Debug [Controller] Killing timer: 61
Debug [Controller] Killing timer: 56
Debug [Controller] Killing timer: 24
Debug [Controller] Killing timer: 65
Debug [Controller] Killing timer: 66
Debug [Controller] Killing timer: 67
Debug [Controller] Killing timer: 71
Debug [Controller] Killing timer: 73
Debug [Controller] Killing timer: 69
Debug [Controller] Killing timer: 13

when starting Mixxx with just ./mixxx
This did not happen before.

daschuer · 2021-11-16T08:17:40Z

When starting with --controller-debug it becomes:

 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 595
 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 596
 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 597
 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 598
 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 599
 controller.djconsolermx2midi1:debug [Controller] Starting one-shot timer: 600

In the terminal only.

While the midi messages are also passed into the mixxx.log

Debug [Controller] "DJConsole Rmx2 MIDI 1: outgoing: status 0x90 (ch 1, opcode 0x9), ctrl 0x12, val 0x00"
Debug [Controller] sending MIDI bytes: 144 , 41 , 0

but without the logging category prefix.

I am not sure if it is desired that the timer messages are in the terminal only. I just want to point it out.

The [Controller] messages have now two time the controller name in the terminal.
We may consider to improve this by printing the logging category to the mixxx.log file as well and remove the controller name from the message itself. Not sure about the implications though.

daschuer · 2021-11-16T08:27:35Z

I am just stumbling over my comment here:
#4239 (comment)

It looks like #2635 was a not working attempt to fix https://bugs.launchpad.net/mixxx/+bug/1871238 we have missed to revert. It was merged on 2020-08-04 to git7232 and we have a report that git7243 is still crashing. It was finally fixed on 2020-04-12 by mixxxdj/buildserver#86.

Can we remove that hack probably the best in a second PR? Or has it an effect here?

Do you have a fresh opinion on that?

ywwg · 2021-11-16T16:02:16Z

thank you for picking up this work <3

Holzhaus · 2021-11-16T20:37:49Z

I am just stumbling over my comment here: #4239 (comment)

It looks like #2635 was a not working attempt to fix https://bugs.launchpad.net/mixxx/+bug/1871238 we have missed to revert. It was merged on 2020-08-04 to git7232 and we have a report that git7243 is still crashing. It was finally fixed on 2020-04-12 by mixxxdj/buildserver#86.

Can we remove that hack probably the best in a second PR? Or has it an effect here?

Do you have a fresh opinion on that?

I'm not sure what you mean exactly, but feel free to open a PR. The lines have not been touched by this PR, so it's out of scope here.

Holzhaus · 2021-11-16T21:02:38Z

timer messages

I'm not sure what you mean, please elaborate. I don't know what you want me to change.

We may consider to improve this by printing the logging category to the mixxx.log file as well and remove the controller name from the message itself.

Yes, someone may implement this in a follow-up PR.

daschuer · 2021-11-16T21:34:25Z

timer messages

I'm not sure what you mean, please elaborate. I don't know what you want me to change.

I don't know how to fix it either. I have only this observation:

Without this patch: no timer log spam
With this patch and without --controllerDebug: timer log spam in mixxx.log
With this patch and with --controllerDebug: timer log spam in terminal

So this patch enables the timer log spam, but it is not considered when disabling controller debug for mixxx.log.

I don't mind if we have the timer messages or not, but It is an issue to flood the mixxx.log by default.

Holzhaus · 2021-11-16T21:52:56Z

Ah, so you want to filter the timer messages from the log file by default, like the MIDI I/O messages are filtered? I did not get that from your previous messages. Please check the latest commit.

daschuer · 2021-11-16T22:06:44Z

I'm not sure what you mean exactly, but feel free to open a PR

It is just the removal of a comment:
#4527

This will be required to use it in a QLoggingCategory which has a deleted copy constructor.

Logging is separated into several subcategores: controller.CONTROLLERNAME: general messages controller.CONTROLLERNAME.input: incoming data controller.CONTROLLERNAME.output: outgoing data CONTROLLERNAME is the lowercase device name with non-alphanumeric characters removed. This allows more fine tuned control of what messages are shown in the console. This is required for the logging output to be useful with controllers that continually send input such as the Native Instruments Traktor Kontrol S4 Mk3 and Gemini GMX.

ywwg · 2021-11-17T00:32:20Z

can confirm, timers no longer printed by default. I would also be ok with a deprecation notice when users use --controllerDebug, but that's not required.

daschuer · 2021-11-17T08:05:07Z

I can also confirm that my test are now working as desired.

daschuer

I have added some minor comments.

src/controllers/midi/portmidicontroller.cpp

src/util/logging.cpp

daschuer

LGTM, Thank you very much :-)

uklotzde · 2021-11-17T14:03:42Z

Thank you all for picking up and finishing this task!

github-actions bot added build code quality controller mappings labels Nov 15, 2021

Swiftb0y reviewed Nov 15, 2021

View reviewed changes

src/test/controller_mapping_validation_test.cpp Outdated Show resolved Hide resolved

src/util/cmdlineargs.cpp Outdated Show resolved Hide resolved

Holzhaus force-pushed the logging-controller-debug branch from 5f961dc to 0ee0b28 Compare November 16, 2021 09:48

Holzhaus marked this pull request as draft November 16, 2021 09:58

Holzhaus mentioned this pull request Nov 16, 2021

Controllers: Use console.log instead of engine.log #4524

Merged

Holzhaus force-pushed the logging-controller-debug branch from 0ee0b28 to 9830a86 Compare November 16, 2021 12:10

Holzhaus force-pushed the logging-controller-debug branch from 9830a86 to 80dc874 Compare November 16, 2021 20:28

Holzhaus force-pushed the logging-controller-debug branch from 80dc874 to 8bb2157 Compare November 16, 2021 21:52

Be-ing and others added 6 commits November 17, 2021 00:16

Controller: make m_sDeviceName const

8fa367b

This will be required to use it in a QLoggingCategory which has a deleted copy constructor.

HSS1394/PortMidiController: remove superfluous QString formatting

be1cd0f

MidiOutputHandler: correct comment

6298841

ControllerDebug: Remove singleton in favor of categorized logging

ed7fb50

Logging: Filter all debug messages from the controller category

03ebbf9

Holzhaus force-pushed the logging-controller-debug branch from 8bb2157 to 03ebbf9 Compare November 16, 2021 23:20

Holzhaus marked this pull request as ready for review November 16, 2021 23:33

daschuer requested changes Nov 17, 2021

View reviewed changes

src/controllers/midi/portmidicontroller.cpp Outdated Show resolved Hide resolved

src/util/logging.cpp Outdated Show resolved Hide resolved

src/util/logging.cpp Show resolved Hide resolved

src/util/logging.cpp Show resolved Hide resolved

Holzhaus added 2 commits November 17, 2021 13:28

Logging: Improve documentation for special --controller-debug logging

81e5fe3

PortMidiController: Check for outputDeviceInfo nullptr in constructor

aa9c7e8

Holzhaus requested a review from daschuer November 17, 2021 13:14

daschuer approved these changes Nov 17, 2021

View reviewed changes

daschuer merged commit dfef281 into mixxxdj:main Nov 17, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Controller logging categories (with --controllerDebug support) #4523

Controller logging categories (with --controllerDebug support) #4523

Holzhaus commented Nov 15, 2021

Swiftb0y left a comment

daschuer commented Nov 16, 2021

daschuer commented Nov 16, 2021

daschuer commented Nov 16, 2021 •

edited

Loading

ywwg commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

daschuer commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

daschuer commented Nov 16, 2021 •

edited

Loading

ywwg commented Nov 17, 2021

daschuer commented Nov 17, 2021

daschuer left a comment

daschuer left a comment

uklotzde commented Nov 17, 2021

Controller logging categories (with --controllerDebug support) #4523

Controller logging categories (with --controllerDebug support) #4523

Conversation

Holzhaus commented Nov 15, 2021

Swiftb0y left a comment

Choose a reason for hiding this comment

daschuer commented Nov 16, 2021

daschuer commented Nov 16, 2021

daschuer commented Nov 16, 2021 • edited Loading

ywwg commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

daschuer commented Nov 16, 2021

Holzhaus commented Nov 16, 2021

daschuer commented Nov 16, 2021 • edited Loading

ywwg commented Nov 17, 2021

daschuer commented Nov 17, 2021

daschuer left a comment

Choose a reason for hiding this comment

daschuer left a comment

Choose a reason for hiding this comment

uklotzde commented Nov 17, 2021

daschuer commented Nov 16, 2021 •

edited

Loading

daschuer commented Nov 16, 2021 •

edited

Loading