Open siilike opened 5 years ago
Thanks for the extended logs, this will help me track down this bug!
I'll try to look at it ASAP.
Any updates on this?
Hi @siilike : I haven't been able to look at this yet, will do so ASAP.
Here's the subscriber log:
[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: ++Loop++ [] []
[2019-08-08 22:48:31] Client.DEBUG: Checking time difference {"secondsDifference":5,"keepAlivePeriod":60} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":1,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: Event received {"ordValue":60,"length":1} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\Publish","controlPacketNumber":3} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":1,"isLocked":false} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":34,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting QoS level {"bitString":60,"incomingQoSLevel":2} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: QoS level above 0, shifting message start position and getting packet identifier [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined packet identifier {"PI":408} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Analyzing first byte ["00111100"] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting redelivery bit [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined headers {"topicSize":9,"QoSLevel":2,"isDuplicate":true,"isRetained":false} []
[2019-08-08 22:48:31] Protocol\Subscribe.DEBUG: ++Loop++ [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Responding with PubRec {"qosLevel":2} []
[2019-08-08 22:48:31] Client.DEBUG: Validating object {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Client.INFO: About to send data {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created variable header {"variableHeader":"AZg="} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created payload {"payload":""} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Creating fixed header with values {"controlPacketValue":5,"specialFlags":0,"variableHeaderLength":2,"composed":"0"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created fixed header {"fixedHeader":"UAI="} []
[2019-08-08 22:48:31] Client.DEBUG: Sent data to socket {"writtenBytes":4,"sizeOfString":4} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":true} []
[2019-08-08 22:48:31] Client.DEBUG: Reading header from response [] []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":4,"isLocked":true} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":false} []
[2019-08-08 22:48:31] Protocol\PubRec.INFO: String of incoming data confirmed, returning new object {"callee":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\Publish","controlPacketNumber":3} []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":32,"isLocked":false} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting QoS level {"bitString":60,"incomingQoSLevel":2} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: QoS level above 0, shifting message start position and getting packet identifier [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined packet identifier {"PI":409} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Analyzing first byte ["00111100"] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Setting redelivery bit [] []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Determined headers {"topicSize":9,"QoSLevel":2,"isDuplicate":true,"isRetained":false} []
[2019-08-08 22:48:31] Client.DEBUG: Checking stack and performing special operations {"originObject":"unreal4u\\MQTT\\Protocol\\PubRec","responseObject":"unreal4u\\MQTT\\Protocol\\Publish"} []
[2019-08-08 22:48:31] Protocol\Publish.DEBUG: Responding with PubRec {"qosLevel":2} []
[2019-08-08 22:48:31] Client.DEBUG: Validating object {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Client.INFO: About to send data {"object":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created variable header {"variableHeader":"AZk="} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created payload {"payload":""} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Creating fixed header with values {"controlPacketValue":5,"specialFlags":0,"variableHeaderLength":2,"composed":"0"} []
[2019-08-08 22:48:31] Protocol\PubRec.DEBUG: Created fixed header {"fixedHeader":"UAI="} []
[2019-08-08 22:48:31] Client.DEBUG: Sent data to socket {"writtenBytes":4,"sizeOfString":4} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":true} []
[2019-08-08 22:48:31] Client.DEBUG: Reading header from response [] []
[2019-08-08 22:48:31] Client.DEBUG: Reading bytes from socket {"numberOfBytes":4,"isLocked":true} []
[2019-08-08 22:48:31] Client.DEBUG: Setting new blocking status {"newStatus":false} []
[2019-08-08 22:48:31] Protocol\PubRec.INFO: String of incoming data confirmed, returning new object {"callee":"unreal4u\\MQTT\\Protocol\\PubRec"} []
[2019-08-08 22:48:31] Internals\EventManager.INFO: Found a matching object, instantiating {"type":"unreal4u\\MQTT\\Protocol\\PubRel","controlPacketNumber":6} []
[2019-08-08 22:48:31] Protocol\PubRel.DEBUG: Determined packet identifier {"PI":"[object] (unreal4u\\MQTT\\DataTypes\\PacketIdentifier: \u0000\u0001)"} []
[2019-08-08 22:48:31] Client.DEBUG: Checking stack and performing special operations {"originObject":"unreal4u\\MQTT\\Protocol\\PubRec","responseObject":"unreal4u\\MQTT\\Protocol\\PubRel"} []
[2019-08-08 22:48:31] Client.DEBUG: Origin packet found, returning it {"originKey":5} []
1, 409
PHP Fatal error: Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php:96
Stack trace:
#0 /data1/tmp/mqtt/src/Protocol/PubRel.php(96): unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers(Object(unreal4u\MQTT\Protocol\PubRec))
#1 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\PubRel->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Protocol\PubRec))
#2 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#3 /data1/tmp/mqtt/src/Client.php(307): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Object(unreal4u\MQTT\Client), Object(unreal4u\MQTT\Application\EmptyWritableResponse))
#4 /data1/tmp/mqtt/src/Protocol/Publish.php(367): unreal4u\MQTT\Client->processObject(Object(unreal4u\MQTT\Protocol\PubRec))
#5 /data1/tmp/mqtt/src/Protocol/Subscribe.php(144): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Obj in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96
Fatal error: Uncaught unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96
unreal4u\MQTT\Exceptions\NonMatchingPacketIdentifiers: Packet identifiers do not match in /data1/tmp/mqtt/src/Internals/PacketIdentifierFunctionality.php on line 96
Call Stack:
0.0002 395952 1. {main}() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:0
0.1695 1833848 2. unreal4u\MQTT\Protocol\Subscribe->loop() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:38
4.5293 1910392 3. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Protocol/Subscribe.php:144
4.5298 1931040 4. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
4.5340 1936112 5. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
4.5342 1936408 6. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
4.5373 1950840 7. unreal4u\MQTT\Protocol\PubRel->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
4.5373 1950840 8. unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers() /data1/tmp/mqtt/src/Protocol/PubRel.php:96
Thanks!
[2019-08-08 22:48:31] Protocol\PubRel.DEBUG: Determined packet identifier {"PI":"[object] (unreal4u\\MQTT\\DataTypes\\PacketIdentifier: \u0000\u0001)"} []
That line is extremely strange, that should be an int and not some unicode characters. My best guess is that the internal counter for the message is off, this could have been introduced during the fix for #9.
I'll try it out and let you know.
You just ran the example file?
Can you confirm that running https://github.com/unreal4u/mqtt/releases/tag/v1.1.0 this version everything is ok? (It will fail however if the message is over 127 bytes, but that is another issue).
Greetings.
Still same issue. I only changed MAXIMUM=10 in b4-publishMessageWithQoS2.php. It works when sleeping between messages, so the issue is how multiple messages are received.
It's easy to test, just get ActiveMQ Artemis, run "bin/artemis create brokertest --user test --password test --allow-anonymous" to create a broker and then "brokertest/bin/artemis run".
Ping. This is probably the best PHP MQTT library, but unusable when this bug is present.
Hi, I have vacations now, so I'm finally able to take a look at this bug. Sorry for the delay but it's been quite busy lately.
Hello, I was wondering about the status of this bug? I love this package, but at the moment it's consistently crashing for me. It's fairly easily reproducible too : if you change MAXIMUM from 1 to 10 in the publishMessageWithQoS2 example, and at the same time have the subscribeMultipleTopics running, you'll see it crash after about 1 or 2 messages, in fact, sometimes it fails to process any messages at all. So it definitely seems to struggle when processing > 1 messages.
I'm not clever enough to attempt to fix it myself :)
Hi @PFRene !
I haven't have made the time yet to fix this, but I have a pretty good idea of where the bug actually is and what I need to do to fix it. It is a not so obvious bug and pretty difficult to fix it in an appropriate manner.
I will be working again soon on this library! Sorry and thanks for the patience!
Your work is much appreciated - looking forward to future updates!
Using latest master, ActiveMQ Artemis and MAXIMUM=10 in example b4:
The relevant identifiers are 1 and 57.
Artemis log: