mqtt icon indicating copy to clipboard operation
mqtt copied to clipboard

Published 20 hours ago • verified publisher icon unreal4u

"Packet identifiers do not match"

Open siilike opened this issue 6 years ago • 11 comments

Using latest master, ActiveMQ Artemis and MAXIMUM=10 in example b4:

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/Client.php(307): unreal4u\MQTT\Protocol\Publish->performSpecialActions(Object(unreal4u 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.0001     395376   1. {main}() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:0
    0.0200    1559032   2. unreal4u\MQTT\Protocol\Subscribe->loop() /data1/tmp/mqtt/examples/d1-subscribeOneTopic.php:32
    5.4410    1700184   3. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Protocol/Subscribe.php:144
    5.4413    1709400   4. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4418    1713352   5. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4418    1713480   6. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4421    1714088   7. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4421    1714216   8. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4423    1714824   9. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4423    1714952  10. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4425    1715560  11. unreal4u\MQTT\Protocol\Publish->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4426    1715688  12. unreal4u\MQTT\Client->processObject() /data1/tmp/mqtt/src/Protocol/Publish.php:367
    5.4445    1726608  13. unreal4u\MQTT\Protocol\PubRel->performSpecialActions() /data1/tmp/mqtt/src/Client.php:307
    5.4445    1726608  14. unreal4u\MQTT\Protocol\PubRel->controlPacketIdentifiers() /data1/tmp/mqtt/src/Protocol/PubRel.php:96

The relevant identifiers are 1 and 57.

Artemis log:

2019-07-27 23:51:32,497 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(): IN << CONNECT protocol=(MQTT, 4), hasPassword=false, isCleanSession=false, keepAliveTimeSeconds=60, clientIdentifier=d1-subscribeOneTopic.php, hasUserName=false, isWillFlag=false
2019-07-27 23:51:32,498 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> CONNACK connectReturnCode=0, sessionPresent=true
2019-07-27 23:51:32,503 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): IN << SUBSCRIBE(50005)
	firstTest : EXACTLY_ONCE
2019-07-27 23:51:32,504 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> SUBACK(50005)
	2
2019-07-27 23:51:37,085 DEBUG [org.apache.activemq.artemis.core.protocol.mqtt] SESSION CREATED: 58b201cf-f0b8-4188-921c-14245fe2a0b4
2019-07-27 23:51:37,086 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(): IN << CONNECT protocol=(MQTT, 4), hasPassword=true, isCleanSession=false, keepAliveTimeSeconds=60, clientIdentifier=b4-publishMessageWithQoS2.php, hasUserName=true, userName=testuser, isWillFlag=false
2019-07-27 23:51:37,086 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> CONNACK connectReturnCode=0, sessionPresent=true
2019-07-27 23:51:37,090 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (1 / 10)
2019-07-27 23:51:37,093 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,093 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(52) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (1 / 10)
2019-07-27 23:51:37,095 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,095 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,097 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (2 / 10)
2019-07-27 23:51:37,099 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,099 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(53) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (2 / 10)
2019-07-27 23:51:37,100 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,100 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,102 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (3 / 10)
2019-07-27 23:51:37,104 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,104 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(54) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (3 / 10)
2019-07-27 23:51:37,106 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,106 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,109 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (4 / 10)
2019-07-27 23:51:37,110 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,111 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(55) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (4 / 10)
2019-07-27 23:51:37,112 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,112 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,113 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (5 / 10)
2019-07-27 23:51:37,115 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,116 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(56) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (5 / 10)
2019-07-27 23:51:37,117 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,117 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,119 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (6 / 10)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBLISH(57) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=true, payload=Hello world!! (6 / 10)
2019-07-27 23:51:37,122 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): IN << PUBREC(52)
2019-07-27 23:51:37,123 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,123 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(1)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(2)
2019-07-27 23:51:37,124 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(3)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(4)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(5)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(6)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(7)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(8)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(9)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(10)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(11)
2019-07-27 23:51:37,125 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (7 / 10)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(12)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(13)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(14)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(15)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(16)
2019-07-27 23:51:37,126 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(d1-subscribeOneTopic.php): OUT >> PUBREL(17)
2019-07-27 23:51:37,128 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,128 WARN  [org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed, clearing up resources for session 50a0f810-b0b0-11e9-b862-28d2444cb448
2019-07-27 23:51:37,128 WARN  [org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for session 50a0f810-b0b0-11e9-b862-28d2444cb448
2019-07-27 23:51:37,130 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,130 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,131 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (8 / 10)
2019-07-27 23:51:37,133 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,135 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,135 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,137 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (9 / 10)
2019-07-27 23:51:37,139 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,140 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,140 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,142 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBLISH(35) topic=firstTest, qos=EXACTLY_ONCE, retain=false, dup=false, payload=Hello world!! (10 / 10)
2019-07-27 23:51:37,144 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBREC(35)
2019-07-27 23:51:37,145 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << PUBREL(35)
2019-07-27 23:51:37,145 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): OUT >> PUBCOMP(35)
2019-07-27 23:51:37,147 TRACE [org.apache.activemq.artemis.core.protocol.mqtt] MQTT(b4-publishMessageWithQoS2.php): IN << DISCONNECT

siilike avatar Jul 27 '19 20:07 siilike

Thanks for the extended logs, this will help me track down this bug!

I'll try to look at it ASAP.

unreal4u avatar Jul 27 '19 22:07 unreal4u

Any updates on this?

siilike avatar Aug 06 '19 09:08 siilike

Hi @siilike : I haven't been able to look at this yet, will do so ASAP.

unreal4u avatar Aug 08 '19 10:08 unreal4u

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

siilike avatar Aug 08 '19 19:08 siilike

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.

unreal4u avatar Aug 24 '19 19:08 unreal4u

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".

siilike avatar Aug 27 '19 07:08 siilike

Ping. This is probably the best PHP MQTT library, but unusable when this bug is present.

siilike avatar Oct 19 '19 10:10 siilike

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.

unreal4u avatar Oct 21 '19 09:10 unreal4u

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 :)

PFRene avatar Sep 08 '20 16:09 PFRene

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!

unreal4u avatar Sep 10 '20 12:09 unreal4u

Your work is much appreciated - looking forward to future updates!

PFRene avatar Sep 10 '20 14:09 PFRene