Set Log callback

[RockyGitHub]

Hello!
I was poking through the C library and saw that you can assign a callback to logging.
This would be really nice to have because then the C library logs can output in this same format as whatever Rust library is being used.
Can this function be exposed in this Rust library?

Thank you!

[fpagliughi]

🤦 OMG. I've been dealing with the C lib for 10yrs now, and I never noticed that!

Yeah, that would be handy, right?

[RockyGitHub]

Haha yes! I'm happy you agree 😃
Thank you for your work on this library!! Am I correct in seeing that others can't contribute since there's some legal/paperwork involved? (Otherwise I'd try to help out)

[fpagliughi]

Yes. All Eclipse Foundation projects require a signed ECA to insure the legal right/ownership to contribute to a project. Remember that Eclipse was started by IBM +20yrs ago when all the big software companies were suing each other over open source code!

But no worries. This should be relatively easy to implement, assuming it works as advertised in the C library. And it's important, and I can use it in my own work. I'll jump on this quickly and get a point release out soon.

[fpagliughi]

OK. I got an initial implementation up in the develop branch. The output is a bit noisy and cryptic, so I used a separate log target/module for the C library messages, named "paho_mqtt_c". That way you can set the levels of the C library and the Rust wrapper separately.

It looks like this:

$ RUST_LOG="info,paho_mqtt_c=debug" ./target/debug/examples/async_subscribe
Connecting to the MQTT server at 'mqtt://localhost:1883'...
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] =========================================================
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client]                    Trace Output
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] Product name: Eclipse Paho Asynchronous MQTT C Client Library
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] Version: 1.3.11
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] Build level: 2023-09-11T13:25:23Z
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] OpenSSL version: OpenSSL 1.1.1f  31 Mar 2020
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] OpenSSL flags: compiler: gcc -fPIC -pthread -m64 -Wa,--noexecstack -Wall -Wa,--noexecstack -g -O2 -fdebug-prefix-map=/build/openssl-mSG92N/openssl-1.1.1f=. -fstack-protector-strong -Wformat -Werror=format-security -DOPENSSL_TLS_SECURITY_LEVEL=2 -DOPENSSL_USE_NODELETE -DL_ENDIAN -DOPENSSL_PIC -DOPENSSL_CPUID_OBJ -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DKECCAK1600_ASM -DRC4_ASM -DMD5_ASM -DAESNI_ASM -DVPAES_ASM -DGHASH_ASM -
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] OpenSSL build timestamp: built on: Wed May 24 17:14:51 2023 UTC
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] OpenSSL platform: platform: debian-amd64
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] OpenSSL directory: OPENSSLDIR: "/usr/lib/ssl"
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] /proc/version: Linux version 5.4.0-162-generic (buildd@lcy02-amd64-069) (gcc version 9.4.0 (Ubuntu 9.4.0-1ubuntu1~20.04.1)) #179-Ubuntu SMP Mon Aug 14 08:51:31 UTC 2023
    
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] =========================================================
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 0 commands restored for client rust_async_subscribe
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 0 queued messages restored for client rust_async_subscribe
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 Connecting to serverURI localhost:1883 with MQTT version 4
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 New socket 3 for localhost:1883, port 1883
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 Connect pending
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 m->c->connect_state = 1
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 3 rust_async_subscribe -> CONNECT version 4 clean: 0 (0)
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 m->c->connect_state = 4
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 3 rust_async_subscribe <- CONNACK rc: 0
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 Calling connect success for client rust_async_subscribe
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 m->c->connect_state = 0
Subscribing to topics: ["test", "hello"]
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 3 rust_async_subscribe <- PUBLISH msgid: 23 qos: 1 retained: 0 payload len(32): Async subscriber los
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 Calling messageArrived for client rust_async_subscribe, queue depth 0
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 3 rust_async_subscribe -> PUBACK msgid: 23 (0)
[2023-09-11T13:26:18Z INFO  paho_mqtt::async_client] 19691231 190000.000 3 rust_async_subscribe -> SUBSCRIBE msgid: 1 (0)
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 m->c->connect_state = 0
[2023-09-11T13:26:18Z DEBUG paho_mqtt::async_client] 19691231 190000.000 Calling subscribe success for client rust_async_subscribe
Waiting for messages...

I'll get some documentation in shortly, and move to release this soon.

[RockyGitHub]

Aaaah amazing 😁😁 you rock!!

[fpagliughi]

One last tweak... I didn't like how it was reporting the logs as coming from the async_client module, so I moved all the new C tracing code, includig the callback, into a new c_trace source file/module. So now it reports the logs from paho_mqtt::c_trace:

$ RUST_LOG="info,paho_mqtt_c=debug" ./target/debug/examples/async_subscribe
Connecting to the MQTT server at 'mqtt://localhost:1883'...
[2023-09-12T12:24:30Z DEBUG paho_mqtt::c_trace] =========================================================
[2023-09-12T12:24:30Z DEBUG paho_mqtt::c_trace]                    Trace Output
[2023-09-12T12:24:30Z DEBUG paho_mqtt::c_trace] Product name: Eclipse Paho Asynchronous MQTT C Client Library
[2023-09-12T12:24:30Z DEBUG paho_mqtt::c_trace] Version: 1.3.11
                            ^^^^^^^^^^^^^^^^^^

[fpagliughi]

Released as v0.12.2

If you notice anything weird with the implementation, feel free to open this back up.

[fpagliughi]

I integrated this into a production system, and it is definitely a little too verbose when running at Info level. Lots of PINGREQ, PINGRESP, PUBLISH, and PUBACK filling up the logs.

Looks like I need to adjust the log levels down a bit.