What steps will reproduce the problem? 1. Just using mod_post_msg and send a message, some messages are swallowed (lost) and are not delivered. 2. Failure often only comes after several messages (like 5 in a row) What do you see instead? Feb 24 09:23:59 c2sdd0238 error Traceback[c2s]: /usr/lib/prosody/modules/mod_offline.lua:38: attempt to index local 'stanza' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_offline.lua:38: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? (tail call): ? /usr/lib/prosody/modules/mod_presence.lua:97: in function 'handle_normal_presence' /usr/lib/prosody/modules/mod_presence.lua:302: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? /usr/lib/prosody/core/stanza_router.lua:190: in function 'core_post_stanza' /usr/lib/prosody/core/stanza_router.lua:137: in function 'core_process_stanza' /usr/lib/prosody/modules/mod_c2s.lua:263: in function 'func' /usr/lib/prosody/util/async.lua:92: in function </usr/lib/prosody/util/async.lua:90> What version of the product are you using? On what operating system? 1nightly845-1~jessie, armhf - Rasberry Pi 2

Debug Log: Feb 24 09:45:44 general info Hello and welcome to Prosody version trunk nightly build 845 (2018-02-23, c3f234e4ac23) Feb 24 09:45:44 stats debug Statistics disabled Feb 24 09:45:44 certmanager debug Searching /etc/prosody/certs for a key and certificate for client_https port 0... Feb 24 09:45:44 certmanager debug No certificate/key found for client_https port 0 Feb 24 09:45:44 general info Prosody is using the select backend for connection handling Feb 24 09:45:44 hostmanager debug Activated host: test-test.org Feb 24 09:45:44 test-test.org:storage_sql debug Creating new engine Feb 24 09:45:44 usermanager debug Host 'test-test.org' now set to use user provider 'internal_hashed' Feb 24 09:45:44 portmanager debug No active service for http, activating... Feb 24 09:45:44 socket debug server.lua: new server listener on '[::]:5280' Feb 24 09:45:44 portmanager debug Added listening service http to [::]:5280 Feb 24 09:45:44 socket debug server.lua: new server listener on '[*]:5280' Feb 24 09:45:44 portmanager debug Added listening service http to [*]:5280 Feb 24 09:45:44 portmanager info Activated service 'http' on [::]:5280, [*]:5280 Feb 24 09:45:44 portmanager debug No active service for https, activating... Feb 24 09:45:44 certmanager debug Searching /etc/prosody/certs/prosody.crt for a key and certificate for https... Feb 24 09:45:44 certmanager debug Selecting certificate /etc/prosody/certs/prosody.crt with key /etc/prosody/certs/prosody.key for https Feb 24 09:45:44 socket debug server.lua: new ssl server listener on '[::]:5281' Feb 24 09:45:44 portmanager debug Added listening service https to [::]:5281 Feb 24 09:45:44 certmanager debug Searching /etc/prosody/certs/prosody.crt for a key and certificate for https... Feb 24 09:45:44 certmanager debug Selecting certificate /etc/prosody/certs/prosody.crt with key /etc/prosody/certs/prosody.key for https Feb 24 09:45:44 socket debug server.lua: new ssl server listener on '[*]:5281' Feb 24 09:45:44 portmanager debug Added listening service https to [*]:5281 Feb 24 09:45:44 portmanager info Activated service 'https' on [::]:5281, [*]:5281 Feb 24 09:45:44 test-test.org:http debug Serving 'bosh' at https://test-test.org:5281/http-bind Feb 24 09:45:45 portmanager debug No active service for s2s, activating... Feb 24 09:45:45 socket debug server.lua: new server listener on '[::]:5269' Feb 24 09:45:45 portmanager debug Added listening service s2s to [::]:5269 Feb 24 09:45:45 socket debug server.lua: new server listener on '[*]:5269' Feb 24 09:45:45 portmanager debug Added listening service s2s to [*]:5269 Feb 24 09:45:45 portmanager info Activated service 's2s' on [::]:5269, [*]:5269 Feb 24 09:45:45 modulemanager debug smacks is already loaded for test-test.org, so not loading again Feb 24 09:45:45 test-test.org:http_files debug http_files_dir not set, assuming use by some other module Feb 24 09:45:45 test-test.org:http debug Serving 'upload' at https://test-test.org:5281/upload Feb 24 09:45:45 test-test.org:http_upload info URL: <https://test-test.org:5281/upload>; Storage path: /home/prosody-http-uploads/ Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/test-test.org.crt with key /etc/prosody/certs/test-test.org.key for test-test.org Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/test-test.org.crt with key /etc/prosody/certs/test-test.org.key for test-test.org Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/test-test.org.crt with key /etc/prosody/certs/test-test.org.key for test-test.org Feb 24 09:45:45 portmanager debug No active service for c2s, activating... Feb 24 09:45:45 socket debug server.lua: new server listener on '[::]:5222' Feb 24 09:45:45 portmanager debug Added listening service c2s to [::]:5222 Feb 24 09:45:45 socket debug server.lua: new server listener on '[*]:5222' Feb 24 09:45:45 portmanager debug Added listening service c2s to [*]:5222 Feb 24 09:45:45 portmanager info Activated service 'c2s' on [::]:5222, [*]:5222 Feb 24 09:45:45 portmanager debug No active service for legacy_ssl, activating... Feb 24 09:45:45 portmanager info Activated service 'legacy_ssl' on no ports Feb 24 09:45:45 modulemanager debug disco is already loaded for test-test.org, so not loading again Feb 24 09:45:45 test-test.org:http debug Serving 'admin' at https://test-test.org:5281/admin Feb 24 09:45:45 mod_posix info Prosody is about to detach from the console, disabling further console output Feb 24 09:45:45 mod_posix info Successfully daemonized to PID 30646 Feb 24 09:45:45 modulemanager debug http_files is already loaded for test-test.org, so not loading again Feb 24 09:45:45 test-test.org:http debug Serving 'mod_post_msg' at https://test-test.org:5281/msg Feb 24 09:45:45 hostmanager debug Activated host: konferenz.test-test.org Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for konferenz.test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/konferenz.test-test.org.crt with key /etc/prosody/certs/konferenz.test-test.org.key for konferenz.test-test.org Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for konferenz.test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/konferenz.test-test.org.crt with key /etc/prosody/certs/konferenz.test-test.org.key for konferenz.test-test.org Feb 24 09:45:45 certmanager debug Searching /etc/prosody/certs for a key and certificate for konferenz.test-test.org... Feb 24 09:45:45 certmanager debug Selecting certificate /etc/prosody/certs/konferenz.test-test.org.crt with key /etc/prosody/certs/konferenz.test-test.org.key for konferenz.test-test.org Feb 24 09:45:45 socket debug server.lua: accepted new client connection from 95.208.189.211:57536 to 5222 Feb 24 09:45:45 c2s185fe30 info Client connected Feb 24 09:45:46 c2s185fe30 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:46 c2s185fe30 debug Sent reply <stream:stream> to client Feb 24 09:45:46 c2s185fe30 debug Not offering authentication on insecure connection Feb 24 09:45:46 c2s185fe30 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Feb 24 09:45:46 socket debug server.lua: we need to do tls, but delaying until send buffer empty Feb 24 09:45:46 c2s185fe30 debug TLS negotiation started for c2s_unauthed... Feb 24 09:45:46 socket debug server.lua: attempting to start tls on tcp{client}: 0x185cc98 Feb 24 09:45:47 socket debug server.lua: ssl handshake done Feb 24 09:45:48 c2s185fe30 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:48 c2s185fe30 debug Sent reply <stream:stream> to client Feb 24 09:45:48 c2s185fe30 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Feb 24 09:45:48 c2s185fe30 debug Offering mechanism PLAIN Feb 24 09:45:48 c2s185fe30 debug Offering mechanism SCRAM-SHA-1 Feb 24 09:45:48 c2s185fe30 debug Offering mechanism SCRAM-SHA-1-PLUS Feb 24 09:45:48 c2s185fe30 debug Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:45:48 sql debug Connecting to [MySQL] prosody... Feb 24 09:45:48 sql debug SQL transaction begin [function(sql.lua:309)] Feb 24 09:45:48 sql debug SQL transaction success [function(sql.lua:309)] Feb 24 09:45:48 sql debug Using encoding 'utf8mb4' for database connection Feb 24 09:45:48 sql debug SQL transaction begin [function(sql.lua:323)] Feb 24 09:45:48 sql debug SQL transaction success [function(sql.lua:323)] Feb 24 09:45:48 sql debug SQL transaction begin [function(sql.lua:329)] Feb 24 09:45:48 sql debug SQL transaction success [function(sql.lua:329)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:467)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:467)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:486)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:486)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:494)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:494)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:522)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:522)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:541)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:541)] Feb 24 09:45:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:48 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:48 test-test.org:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1HblVNOWZZZGErdStGcVVWeE11TWlGV1NGbTlpRTB3UVlJZ3VFNUJySGpPdEpiOVFzSzRkUHNHOU1kNUEzNFpSK2Y2ZDZsRUFET0QwRm1Qd3VTQTlBZVpJaXdOZVRvS2VxbVU2blJ1RG9ZcjFFQS9KLzNBUXhEZFE1U3RxdVg4ZHJZSEpKUTMyOWRkZmMwLWVkMmItNDgyMC1iYzE4LWE3ZjMyZTIwMTcxZixzPVltRmhORFJsTkdNdE1qYzBNaTAwWVRabExUZzBNekl0T1daalpHTXpOamN6TVRjNSxpPTQwOTY=</challenge> Feb 24 09:45:48 c2s185fe30 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:45:48 c2s185fe30 info Authenticated as kurfisc@test-test.org Feb 24 09:45:48 test-test.org:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1VbXFCSmxnUWNLSmxvR2I2eElwNVJxRUxNWTg9</success> Feb 24 09:45:48 c2s185fe30 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:48 c2s185fe30 debug Sent reply <stream:stream> to client Feb 24 09:45:49 c2s185fe30 debug Received[c2s_unbound]: <resume h='33' previd='43f45f3d-8c1c-4615-b8af-8afad54eea2b' xmlns='urn:xmpp:sm:3'> Feb 24 09:45:49 c2s185fe30 debug Tried to resume non-existent session with id 43f45f3d-8c1c-4615-b8af-8afad54eea2b Feb 24 09:45:49 c2s185fe30 debug Received[c2s_unbound]: <iq id='XwvYvwxVDXszCJA+6WccZrQgT51q8Ro7UE78SE39gbgj9lANssvWL/p7wGb/AD8peCk' type='set'> Feb 24 09:45:49 rostermanager debug load_roster: asked for: kurfisc@test-test.org Feb 24 09:45:49 rostermanager debug load_roster: loading for new user: kurfisc@test-test.org Feb 24 09:45:49 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:49 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:49 mod_admin_web debug Added client kurfisc@test-test.org/phone Feb 24 09:45:49 c2s185fe30 debug Resource bound: kurfisc@test-test.org/phone Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'> Feb 24 09:45:50 test-test.org:smacks debug Enabling stream management Feb 24 09:45:50 c2s185fe30 debug Handled 1 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='/zfQM7WhNNWdMw3KkEBEQn+jpbvCFfip9PirsbnyKmdPXxveLcDXtqinT++xgAtjpvw' type='get' to='kurfisc@test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 1 Feb 24 09:45:50 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:50 c2s185fe30 debug Handled 2 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='gmTEJ7ziLtj/RzPIBGXpxKltM0RT+hRv11Ng44s+qyJ0h2loTNT5AfULXVgLq7eeiKY' type='get' to='test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 2 Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:45:50 test-test.org:smacks debug Received ack request, acking for 2 Feb 24 09:45:50 c2s185fe30 debug Handled 3 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='gUe6dh/3RYCfAfmn67xPdwdejLIFiiLMpz7JRwNt2eECFXKLSKVmJRj7nSOj+wUL0NI' type='set' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 test-test.org:carbons debug kurfisc@test-test.org/phone enabled carbons Feb 24 09:45:50 c2s185fe30 debug #queue = 3 Feb 24 09:45:50 c2s185fe30 debug Handled 4 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='WpmYM7N3+f05TjZNAG/Yk2EoUuyfqATVvp3b65AoopT0MBDt+/d5LsWvgI10viydJSQ' type='get' to='konferenz.test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 4 Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2'> Feb 24 09:45:50 c2s185fe30 debug #queue = 2 Feb 24 09:45:50 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:50 c2s185fe30 debug Handled 5 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='xQ6i5oBPEmiPz1NkQeKAOpkNTMDgSy2X9Pf3ztFGdwD9V561x2DOiMxoOZdazmuxcuI' type='get' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 3 Feb 24 09:45:50 c2s185fe30 debug Handled 6 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='Rta9fObwKL3ZUt/l44+rN92WdrXSKU0CBniXzVQTeWTBSFtQXU993EtlzeBPAYsQDHw' type='get' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:150)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:150)] Feb 24 09:45:50 c2s185fe30 debug #queue = 4 Feb 24 09:45:50 c2s185fe30 debug Handled 7 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <presence from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 5 Feb 24 09:45:50 c2s185fe30 debug #queue = 6 Feb 24 09:45:50 test-test.org:presence debug outbound presence probe from kurfisc@test-test.org for clafisc@test-test.org Feb 24 09:45:50 test-test.org:presence debug inbound presence probe from kurfisc@test-test.org for clafisc@test-test.org Feb 24 09:45:50 test-test.org:presence debug broadcasted presence of 0 resources from clafisc@test-test.org to kurfisc@test-test.org/phone Feb 24 09:45:50 c2s185fe30 debug #queue = 7 Feb 24 09:45:50 test-test.org:presence debug outbound presence probe from kurfisc@test-test.org for kafisc@test-test.org Feb 24 09:45:50 test-test.org:presence debug inbound presence probe from kurfisc@test-test.org for kafisc@test-test.org Feb 24 09:45:50 test-test.org:presence debug broadcasted presence of 0 resources from kafisc@test-test.org to kurfisc@test-test.org/phone Feb 24 09:45:50 c2s185fe30 debug #queue = 8 Feb 24 09:45:50 test-test.org:presence debug outbound presence subscribe from kurfisc@test-test.org for homematic@test-test.org Feb 24 09:45:50 rostermanager debug load_roster: asked for: kurfisc@test-test.org Feb 24 09:45:50 c2s185fe30 debug #queue = 9 Feb 24 09:45:50 test-test.org:presence debug inbound presence subscribe from kurfisc@test-test.org for homematic@test-test.org Feb 24 09:45:50 c2s185fe30 debug #queue = 10 Feb 24 09:45:50 rostermanager debug load_roster: asked for: homematic@test-test.org Feb 24 09:45:50 rostermanager debug load_roster: loading for offline user: homematic@test-test.org Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:367)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:367)] Feb 24 09:45:50 c2s185fe30 debug Handled 8 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='JsFUZbPYBVWntPxM6eN8jB0LrDBsaN8ulVe/jIO9u6HBaIiBgLiHVF/RbY8wrLnHYZw' type='set' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 test-test.org:mam debug Archive query, id fn6rgr30h0 with anyone from the dawn of time until 2018-02-24T08:45:49Z) Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:45:50 test-test.org:mam debug Archive query fn6rgr30h0 completed Feb 24 09:45:50 c2s185fe30 debug #queue = 11 Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <inactive xmlns='urn:xmpp:csi:0'> Feb 24 09:45:50 c2s185fe30 debug Handled 9 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/kurfisc' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:50 konferenz.test-test.org:muc debug Restoring room 1585i9kspcst5@konferenz.test-test.org from storage Feb 24 09:45:50 c2s185fe30 debug Handled 10 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='tRKEXmxWVF4AIV/Rb7HENNPzSNjpmdCdjYH7NeE5iYefHTe0iyp3cXzQzjgiuMasZwM' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 12 Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='4'> Feb 24 09:45:50 c2s185fe30 debug #queue = 10 Feb 24 09:45:50 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:50 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:50 c2s185fe30 debug Handled 11 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='disco' type='result' to='kurfisc@test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 stanzarouter debug Discarding iq from c2s of type: result Feb 24 09:45:50 c2s185fe30 debug Handled 12 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <presence to='1585i9kspcst5@konferenz.test-test.org/kurfisc' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 konferenz.test-test.org:muc debug no occupant found for 1585i9kspcst5@konferenz.test-test.org/kurfisc; creating new occupant object for kurfisc@test-test.org/phone Feb 24 09:45:50 c2s185fe30 debug #queue = 11 Feb 24 09:45:50 test-test.org:mam debug Not archiving stanza: <message id='6ad97b23-c546-4837-8873-383f70aa37d4' type='groupchat' to='kurfisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org/kurfisc'> (type) Feb 24 09:45:50 c2s185fe30 debug #queue = 12 Feb 24 09:45:50 test-test.org:mam debug Not archiving stanza: <message type='groupchat' to='kurfisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org'> (type) Feb 24 09:45:50 c2s185fe30 debug #queue = 13 Feb 24 09:45:50 socket debug server.lua: accepted new client connection from 95.208.189.211:35769 to 5222 Feb 24 09:45:50 c2s18a4a10 info Client connected Feb 24 09:45:50 c2s185fe30 debug Handled 13 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='eTsaVZU9wDwtVLBH+u78V3j5YrAyFA37IYRmV2ScKoxYU02o3BNUaDu3IfHgpN+ftNY' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 14 Feb 24 09:45:50 c2s185fe30 debug Handled 14 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='WX4eLCFNDl25AvqHmvqgOIyfx+e7ZAoBkk0bAVpW+f/dAHuNHsBkbr94XFYjwfpvfBo' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:50 c2s185fe30 debug #queue = 15 Feb 24 09:45:50 c2s185fe30 debug Handled 15 incoming stanzas Feb 24 09:45:50 c2s185fe30 debug Received[c2s]: <iq id='NQVNGWtdHP7Vt7/Nw4wy0QQQLv2AU50o9BV3pWW979MkML7WuQhIylwNqz37IwAU2LU' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kurfisc@test-test.org/phone'> Feb 24 09:45:51 c2s185fe30 debug #queue = 16 Feb 24 09:45:51 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='14'> Feb 24 09:45:51 c2s185fe30 debug #queue = 6 Feb 24 09:45:51 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:51 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:51 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:51 c2s18a4a10 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:51 c2s18a4a10 debug Sent reply <stream:stream> to client Feb 24 09:45:51 c2s18a4a10 debug Not offering authentication on insecure connection Feb 24 09:45:51 c2s18a4a10 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Feb 24 09:45:51 socket debug server.lua: we need to do tls, but delaying until send buffer empty Feb 24 09:45:51 c2s18a4a10 debug TLS negotiation started for c2s_unauthed... Feb 24 09:45:51 socket debug server.lua: attempting to start tls on tcp{client}: 0x1657228 Feb 24 09:45:51 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='20'> Feb 24 09:45:51 c2s185fe30 debug #queue = 0 Feb 24 09:45:52 socket debug server.lua: ssl handshake done Feb 24 09:45:53 socket debug server.lua: accepted new client connection from 95.208.189.211:49420 to 5280 Feb 24 09:45:53 http.server debug Firing event: POST test-test.org/msg/kafisc@test-test.org Feb 24 09:45:53 test-test.org:auth_internal_hashed debug test password for user 'homematic' Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 test-test.org:mod_post_msg debug Authed as homematic@test-test.org Feb 24 09:45:53 test-test.org:mod_post_msg debug Sending <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'><body>Zeichenlaenge angepasst</body></message> Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 test-test.org:mam debug kafisc's rule for homematic@test-test.org is nil Feb 24 09:45:53 test-test.org:mam debug kafisc's default rule is true Feb 24 09:45:53 test-test.org:mam debug Archiving stanza: <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'> Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:45:53 test-test.org:carbons debug Skip carbons for offline user Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:45:53 socket debug server.lua: client 95.208.189.211:49420 read error: closed Feb 24 09:45:53 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:45:53 c2s18a4a10 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:53 c2s18a4a10 debug Sent reply <stream:stream> to client Feb 24 09:45:53 c2s18a4a10 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Feb 24 09:45:53 c2s18a4a10 debug Offering mechanism PLAIN Feb 24 09:45:53 c2s18a4a10 debug Offering mechanism SCRAM-SHA-1 Feb 24 09:45:53 c2s18a4a10 debug Offering mechanism SCRAM-SHA-1-PLUS Feb 24 09:45:53 c2s18a4a10 debug Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:45:53 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:53 test-test.org:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1pWDAvLythNjRudEUxNTRNZG9QUVBIVjF1bm5pdWhIbFY3VjFNNHpDNHMrSUJKdGhoWDFlWWpSZlEwNDVMTU1aRUpCdnBpNk1jV0t3blRzQzBLeVVvVFJKc3NheC9jRTZtUFRrWitxaDlYOHEyVlBwSzA1QVM2bUV6VFFWbWxCK25WTGJrdzBhNjk5M2M0LWI1YjUtNDg3NS1iOGVlLTI4MjExYjZlOTliMixzPU16YzBORGxrTldZdFltSmtaUzAwTURobUxXRXlZelV0WlRZNU1HWmxaVFJrT1RJMCxpPTQwOTY=</challenge> Feb 24 09:45:53 c2s18a4a10 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:45:53 c2s18a4a10 info Authenticated as clafisc@test-test.org Feb 24 09:45:53 test-test.org:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj03M05kMzVEZzAwd0hFeFkyZXpOcHpPcUd4QmM9</success> Feb 24 09:45:53 c2s18a4a10 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:45:53 c2s18a4a10 debug Sent reply <stream:stream> to client Feb 24 09:45:54 c2s18a4a10 debug Received[c2s_unbound]: <resume h='36' previd='5cf17d7a-2d7e-49c2-b519-9722455bd66a' xmlns='urn:xmpp:sm:3'> Feb 24 09:45:54 c2s18a4a10 debug Tried to resume non-existent session with id 5cf17d7a-2d7e-49c2-b519-9722455bd66a Feb 24 09:45:54 c2s18a4a10 debug Received[c2s_unbound]: <iq id='btXA47j4IrUC5IvsTbbP2uzWz+Z5Sh24sLlp9bMIPzm7O67gHEGg5CFlzMC3UhRAIPo' type='set'> Feb 24 09:45:54 rostermanager debug load_roster: asked for: clafisc@test-test.org Feb 24 09:45:54 rostermanager debug load_roster: loading for new user: clafisc@test-test.org Feb 24 09:45:54 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:54 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:54 mod_admin_web debug Added client clafisc@test-test.org/tablet Feb 24 09:45:54 c2s18a4a10 debug Resource bound: clafisc@test-test.org/tablet Feb 24 09:45:54 c2s18a4a10 debug Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'> Feb 24 09:45:54 test-test.org:smacks debug Enabling stream management Feb 24 09:45:55 c2s18a4a10 debug Handled 1 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='vxYWFh9G1ed9y9DEPxEDxBQ7s/BzkyEL7V8sT6mO62Hj9chwP02WSHwmAh/XEtcpxcc' type='get' to='clafisc@test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 1 Feb 24 09:45:55 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:45:55 c2s18a4a10 debug Handled 2 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='Dw3F1yik1xqLOg83zCBKggPHrotlpwu/7JcVZayw0WJyCr0ApIY5talNwjPVrRnDHno' type='get' to='test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 2 Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:45:55 test-test.org:smacks debug Received ack request, acking for 2 Feb 24 09:45:55 c2s18a4a10 debug Handled 3 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='Yscl1h1tLfqqAs2hm+D0bCFLqdVMbECSLqADp9nCcyKEtA48SBwaSLE6UPAMg4Uk6lA' type='set' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 test-test.org:carbons debug clafisc@test-test.org/tablet enabled carbons Feb 24 09:45:55 c2s18a4a10 debug #queue = 3 Feb 24 09:45:55 c2s18a4a10 debug Handled 4 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='uSumVhJEB/KH9EbBjn7exDsufXlNYTurFlBr8r6AwaEUlbx9EE9LMCTJer21va3x1Ew' type='get' to='konferenz.test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 4 Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 2 Feb 24 09:45:55 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:45:55 c2s18a4a10 debug Handled 5 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='zI4rmfcYdOXqx2T74nPR4Z8FLqx35sGhjitfL4g/l3xjAiCDCunNFEt9yxEc1NxYDRI' type='get' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 3 Feb 24 09:45:55 c2s18a4a10 debug Handled 6 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='hdVLEP4aA5gzjipluF5gfzm7aSmKB69KX/EEoHxz6DUYt+5dkqetIJqCXwDV4+Sapw0' type='get' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 sql debug SQL transaction begin [function(mod_storage_sql.lua:150)] Feb 24 09:45:55 sql debug SQL transaction success [function(mod_storage_sql.lua:150)] Feb 24 09:45:55 c2s18a4a10 debug #queue = 4 Feb 24 09:45:55 c2s18a4a10 debug Handled 7 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <presence from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 5 Feb 24 09:45:55 c2s18a4a10 debug #queue = 6 Feb 24 09:45:55 c2s185fe30 debug #queue = 1 Feb 24 09:45:55 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:55 test-test.org:presence debug outbound presence probe from clafisc@test-test.org for kafisc@test-test.org Feb 24 09:45:55 test-test.org:presence debug inbound presence probe from clafisc@test-test.org for kafisc@test-test.org Feb 24 09:45:55 test-test.org:presence debug broadcasted presence of 0 resources from kafisc@test-test.org to clafisc@test-test.org/tablet Feb 24 09:45:55 c2s18a4a10 debug #queue = 7 Feb 24 09:45:55 test-test.org:presence debug outbound presence probe from clafisc@test-test.org for kurfisc@test-test.org Feb 24 09:45:55 test-test.org:presence debug inbound presence probe from clafisc@test-test.org for kurfisc@test-test.org Feb 24 09:45:55 c2s18a4a10 debug #queue = 8 Feb 24 09:45:55 test-test.org:presence debug broadcasted presence of 1 resources from kurfisc@test-test.org to clafisc@test-test.org/tablet Feb 24 09:45:55 test-test.org:presence debug outbound presence subscribe from clafisc@test-test.org for homematic@test-test.org Feb 24 09:45:55 rostermanager debug load_roster: asked for: clafisc@test-test.org Feb 24 09:45:55 c2s18a4a10 debug #queue = 9 Feb 24 09:45:55 test-test.org:presence debug inbound presence subscribe from clafisc@test-test.org for homematic@test-test.org Feb 24 09:45:55 c2s18a4a10 debug #queue = 10 Feb 24 09:45:55 rostermanager debug load_roster: asked for: homematic@test-test.org Feb 24 09:45:55 rostermanager debug load_roster: loading for offline user: homematic@test-test.org Feb 24 09:45:55 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:45:55 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:45:55 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:45:55 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:45:55 sql debug SQL transaction begin [function(mod_storage_sql.lua:367)] Feb 24 09:45:55 sql debug SQL transaction success [function(mod_storage_sql.lua:367)] Feb 24 09:45:55 c2s18a4a10 debug Handled 8 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='izmW3ukAQIVJjQOJbLBHJZUQ3gYmekU2L5+PpeQwWxzQPhFR2PalWJ1SWXb5t2IgeDc' type='set' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 test-test.org:mam debug Archive query, id qn0voh7edk with anyone from the dawn of time until 2018-02-24T08:45:54Z) Feb 24 09:45:55 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:45:55 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:45:55 c2s18a4a10 debug #queue = 11 Feb 24 09:45:55 c2s18a4a10 debug #queue = 12 Feb 24 09:45:55 test-test.org:mam debug Archive query qn0voh7edk completed Feb 24 09:45:55 c2s18a4a10 debug #queue = 13 Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <inactive xmlns='urn:xmpp:csi:0'> Feb 24 09:45:55 c2s18a4a10 debug Handled 9 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/clafisc' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug Handled 10 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='ZDzyP1KGzGHXKGSlneojyMBuIzdr1zbnqOHKwA7xUuD3AEOkoCQdbuKiBVjbwoAwAQg' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 14 Feb 24 09:45:55 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:55 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='4'> Feb 24 09:45:55 c2s18a4a10 debug #queue = 12 Feb 24 09:45:55 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:45:55 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:45:55 c2s18a4a10 debug Handled 11 incoming stanzas Feb 24 09:45:55 c2s18a4a10 debug Received[c2s]: <iq id='disco' type='result' to='clafisc@test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:55 stanzarouter debug Discarding iq from c2s of type: result Feb 24 09:45:55 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='21'> Feb 24 09:45:55 c2s185fe30 debug #queue = 0 Feb 24 09:45:56 c2s18a4a10 debug Handled 12 incoming stanzas Feb 24 09:45:56 c2s18a4a10 debug Received[c2s]: <presence to='1585i9kspcst5@konferenz.test-test.org/clafisc' from='clafisc@test-test.org/tablet'> Feb 24 09:45:56 konferenz.test-test.org:muc debug no occupant found for 1585i9kspcst5@konferenz.test-test.org/clafisc; creating new occupant object for clafisc@test-test.org/tablet Feb 24 09:45:56 c2s18a4a10 debug #queue = 13 Feb 24 09:45:56 c2s185fe30 debug #queue = 1 Feb 24 09:45:56 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:45:56 c2s18a4a10 debug #queue = 14 Feb 24 09:45:56 test-test.org:mam debug Not archiving stanza: <message id='6ad97b23-c546-4837-8873-383f70aa37d4' type='groupchat' to='clafisc@test-test.org/tablet' from='1585i9kspcst5@konferenz.test-test.org/kurfisc'> (type) Feb 24 09:45:56 c2s18a4a10 debug #queue = 15 Feb 24 09:45:56 test-test.org:mam debug Not archiving stanza: <message type='groupchat' to='clafisc@test-test.org/tablet' from='1585i9kspcst5@konferenz.test-test.org'> (type) Feb 24 09:45:56 c2s18a4a10 debug #queue = 16 Feb 24 09:45:56 c2s18a4a10 debug Handled 13 incoming stanzas Feb 24 09:45:56 c2s18a4a10 debug Received[c2s]: <iq id='DTrkxPL3o8VEHQ31yErpYXAtejxQt9+B7EMZdenPZ5b7OeatDjSiHimfXHYghlKpIa0' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:56 c2s18a4a10 debug #queue = 17 Feb 24 09:45:56 c2s18a4a10 debug Handled 14 incoming stanzas Feb 24 09:45:56 c2s18a4a10 debug Received[c2s]: <iq id='7i+nZiIeNHnsR8CLmLEMbBudxZGfYUKBv/ZUh1uqeMfD2R7q6vDqK4T+s7BHnOizfdE' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:56 c2s18a4a10 debug #queue = 18 Feb 24 09:45:56 c2s18a4a10 debug Handled 15 incoming stanzas Feb 24 09:45:56 c2s18a4a10 debug Received[c2s]: <iq id='pO7VbADmEnSf2i5Odn3r/o8smb8yPi1F+JOlyPjA58b/AuypZ2o/gs20wEP/nJzk1/E' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/tablet'> Feb 24 09:45:56 c2s18a4a10 debug #queue = 19 Feb 24 09:45:56 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='16'> Feb 24 09:45:56 c2s18a4a10 debug #queue = 7 Feb 24 09:45:56 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:45:56 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:45:56 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:45:56 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:45:56 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:45:57 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='23'> Feb 24 09:45:57 c2s18a4a10 debug #queue = 0 Feb 24 09:45:57 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='22'> Feb 24 09:45:57 c2s185fe30 debug #queue = 0 Feb 24 09:46:01 socket debug server.lua: accepted new client connection from 95.208.189.211:49362 to 5222 Feb 24 09:46:01 c2s15943c0 info Client connected Feb 24 09:46:01 c2s15943c0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:01 c2s15943c0 debug Sent reply <stream:stream> to client Feb 24 09:46:01 c2s15943c0 debug Not offering authentication on insecure connection Feb 24 09:46:01 c2s15943c0 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Feb 24 09:46:01 socket debug server.lua: we need to do tls, but delaying until send buffer empty Feb 24 09:46:01 c2s15943c0 debug TLS negotiation started for c2s_unauthed... Feb 24 09:46:01 socket debug server.lua: attempting to start tls on tcp{client}: 0x16468c0 Feb 24 09:46:05 socket debug server.lua: ssl handshake done Feb 24 09:46:05 c2s15943c0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:05 c2s15943c0 debug Sent reply <stream:stream> to client Feb 24 09:46:05 c2s15943c0 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Feb 24 09:46:05 c2s15943c0 debug Offering mechanism PLAIN Feb 24 09:46:05 c2s15943c0 debug Offering mechanism SCRAM-SHA-1 Feb 24 09:46:05 c2s15943c0 debug Offering mechanism SCRAM-SHA-1-PLUS Feb 24 09:46:05 socket debug server.lua: accepted new client connection from 95.208.189.211:49466 to 5280 Feb 24 09:46:05 http.server debug Firing event: POST test-test.org/msg/kafisc@test-test.org Feb 24 09:46:05 test-test.org:auth_internal_hashed debug test password for user 'homematic' Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 test-test.org:mod_post_msg debug Authed as homematic@test-test.org Feb 24 09:46:05 test-test.org:mod_post_msg debug Sending <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'><body>Zeichenlaenge angepasst</body></message> Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 test-test.org:mam debug kafisc's rule for homematic@test-test.org is nil Feb 24 09:46:05 test-test.org:mam debug kafisc's default rule is true Feb 24 09:46:05 test-test.org:mam debug Archiving stanza: <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'> Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:05 test-test.org:carbons debug Skip carbons for offline user Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:05 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:05 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:05 socket debug server.lua: client 95.208.189.211:49466 read error: closed Feb 24 09:46:05 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:46:06 c2s15943c0 debug Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:46:06 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:06 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:06 test-test.org:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1CZzhDK2c5b0ZvODFCUzdHSDdIcUJnczVnWDJnbVRKb05VYXF3bWQyNExVMndOUWVhZk9kNXdZays0TVRGeHd3WDlFZzBWVVArc2thaUlMSGRFdUtmL2pJZElyVk9pMVFTcHJhV0NNQk5TcDlhTndZeXpKSmhoaUFoR3hrTmZTQ2w1d3ZSUTYyNzNlNWM2LTczNmMtNGIyOS1iODZjLWMyNmRhMWYzYTc3NixzPU16YzBORGxrTldZdFltSmtaUzAwTURobUxXRXlZelV0WlRZNU1HWmxaVFJrT1RJMCxpPTQwOTY=</challenge> Feb 24 09:46:08 c2s15943c0 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:46:08 c2s15943c0 info Authenticated as clafisc@test-test.org Feb 24 09:46:08 test-test.org:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1ZZ25EdWJrSVlEaXdwV3NOSEFsa0RoUHhNRTA9</success> Feb 24 09:46:09 c2s15943c0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:09 c2s15943c0 debug Sent reply <stream:stream> to client Feb 24 09:46:11 c2s15943c0 debug Received[c2s_unbound]: <resume h='29' previd='043fa6d4-9cbd-4cb3-a8e2-45fa45082b05' xmlns='urn:xmpp:sm:3'> Feb 24 09:46:11 c2s15943c0 debug Tried to resume non-existent session with id 043fa6d4-9cbd-4cb3-a8e2-45fa45082b05 Feb 24 09:46:12 c2s15943c0 debug Received[c2s_unbound]: <iq id='vjJBpiudjzQh5nXfY5UbJxYpVfXtpITfgeKawki6VU3+pAKuTXB7JSwgTbsX7OlUgo0' type='set'> Feb 24 09:46:12 rostermanager debug load_roster: asked for: clafisc@test-test.org Feb 24 09:46:12 mod_admin_web debug Added client clafisc@test-test.org/phone Feb 24 09:46:12 c2s15943c0 debug Resource bound: clafisc@test-test.org/phone Feb 24 09:46:17 c2s15943c0 debug Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'> Feb 24 09:46:17 test-test.org:smacks debug Enabling stream management Feb 24 09:46:17 c2s15943c0 debug Handled 1 incoming stanzas Feb 24 09:46:17 c2s15943c0 debug Received[c2s]: <iq id='9kTzAh8fUWZvC+hs55he03JSJ45hFZgl+kBJt2Kwpca0TdTpnMxlqeUknqAF3BOgyQQ' type='get' to='clafisc@test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:17 c2s15943c0 debug #queue = 1 Feb 24 09:46:17 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:46:17 c2s15943c0 debug Handled 2 incoming stanzas Feb 24 09:46:17 c2s15943c0 debug Received[c2s]: <iq id='bOovbqbWDOCdLppa8sldl/75TkG73P/bwO2ch5KBF6Md69mfJtqBStKaNVx6njx+EHE' type='get' to='test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:17 c2s15943c0 debug #queue = 2 Feb 24 09:46:17 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:46:17 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:46:17 c2s15943c0 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:46:17 test-test.org:smacks debug Received ack request, acking for 2 Feb 24 09:46:17 socket debug server.lua: accepted new client connection from 95.208.189.211:42235 to 5222 Feb 24 09:46:17 c2s18b4cf0 info Client connected Feb 24 09:46:17 c2s18b4cf0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:17 c2s18b4cf0 debug Sent reply <stream:stream> to client Feb 24 09:46:17 c2s18b4cf0 debug Not offering authentication on insecure connection Feb 24 09:46:17 c2s18b4cf0 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Feb 24 09:46:17 socket debug server.lua: we need to do tls, but delaying until send buffer empty Feb 24 09:46:17 c2s18b4cf0 debug TLS negotiation started for c2s_unauthed... Feb 24 09:46:17 socket debug server.lua: attempting to start tls on tcp{client}: 0x16c7238 Feb 24 09:46:18 c2s15943c0 debug Handled 3 incoming stanzas Feb 24 09:46:18 c2s15943c0 debug Received[c2s]: <iq id='yopp0Ofbe8bUa9EA9iyhvzaNt7Xh+e3jPvOeKM9C0CPsd77Mpy7nP2CKeNvKKYH/MqY' type='set' from='clafisc@test-test.org/phone'> Feb 24 09:46:18 test-test.org:carbons debug clafisc@test-test.org/phone enabled carbons Feb 24 09:46:18 c2s15943c0 debug #queue = 3 Feb 24 09:46:18 socket debug server.lua: ssl handshake done Feb 24 09:46:18 c2s18b4cf0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:18 c2s18b4cf0 debug Sent reply <stream:stream> to client Feb 24 09:46:18 c2s18b4cf0 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Feb 24 09:46:18 c2s18b4cf0 debug Offering mechanism PLAIN Feb 24 09:46:18 c2s18b4cf0 debug Offering mechanism SCRAM-SHA-1 Feb 24 09:46:18 c2s18b4cf0 debug Offering mechanism SCRAM-SHA-1-PLUS Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 test-test.org:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1wZjBsb0p2YTh0Y1F4bGRpYjkrc05NZnJCR1VNMWVVKzRqMEg4L2h3eVEycTVKQjNmeGhEaXU3bUo3MGhBV1A4TWd3dGhTUGcwUUpNSVlFemNVbFQ4M3h0RkpSOXd0Sjh2bHZhSkhZanZ6dllRbWtkOWhteEpGVC9DZ29ta0xQRkJuOTdpd2MxZDRjODVkLWQ0MWMtNDQ0NC05YjZmLTVlNWVlZTk5YjgyYyxzPU1USmpZV1JpWVdVdE1qUXhPQzAwTkdOaExXRm1NelV0T1dFelpqYzBabVkwWWpnMixpPTQwOTY=</challenge> Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:46:18 c2s18b4cf0 info Authenticated as kafisc@test-test.org Feb 24 09:46:18 test-test.org:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1oNkxkdy92b1M5aU0rWWZiVnNFbGpkY09VQ1U9</success> Feb 24 09:46:18 c2s18b4cf0 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:46:18 c2s18b4cf0 debug Sent reply <stream:stream> to client Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s_unbound]: <resume h='66' previd='f7de57ab-1f40-473a-943a-79a2bea3f68d' xmlns='urn:xmpp:sm:3'> Feb 24 09:46:18 c2s18b4cf0 debug Tried to resume non-existent session with id f7de57ab-1f40-473a-943a-79a2bea3f68d Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s_unbound]: <iq id='il2IryoKCmVGfdqYPIe0AmVrouuTp2GIPN8afF8RygxIXqDcsDz3s+pxT4EM6RjOlUs' type='set'> Feb 24 09:46:18 rostermanager debug load_roster: asked for: kafisc@test-test.org Feb 24 09:46:18 rostermanager debug load_roster: loading for new user: kafisc@test-test.org Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 mod_admin_web debug Added client kafisc@test-test.org/phone Feb 24 09:46:18 c2s18b4cf0 debug Resource bound: kafisc@test-test.org/phone Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'> Feb 24 09:46:18 test-test.org:smacks debug Enabling stream management Feb 24 09:46:18 c2s18b4cf0 debug Handled 1 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='PeTj2MiCe12Mb+01PaV0/zOw5UoqrHuZ4nIXCG6h9vOZcHWrhnjFcmlAJGnynOrEXpE' type='get' to='kafisc@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 1 Feb 24 09:46:18 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s18b4cf0 debug Handled 2 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='drdbqJCo/7bbfC35y5tO8oyCpelDf5k1hfrQw6uSp1CMUt7NlWwL2SDMLQIoVqMNr5c' type='get' to='test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 2 Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:46:18 test-test.org:smacks debug Received ack request, acking for 2 Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s18b4cf0 debug Handled 3 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='03y0yjfPp/gKsqRGmGLlAgU/0kOCpo1/dYrM79oHLjWUDLPRROvBdis7DryiBcIWNMs' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 test-test.org:carbons debug kafisc@test-test.org/phone enabled carbons Feb 24 09:46:18 c2s18b4cf0 debug #queue = 3 Feb 24 09:46:18 c2s18b4cf0 debug Handled 4 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='45CTB3HrafzNEMu1TBLCv9wGVO0LC29zXIjPveS86dqJiVP+lHuLoMho17/5rzYu6WU' type='get' to='konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 4 Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 2 Feb 24 09:46:18 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s18b4cf0 debug Handled 5 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='JmM3n7zdrLQR8R7+AzCZI8TF/L2Wrx3dEm18d0xDUg/9q4IJ+l3O0mPiOjrSwKDTKj8' type='get' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 3 Feb 24 09:46:18 c2s18b4cf0 debug Handled 6 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='lXE9Q7X6XUcN3c/sMSNpwcBVZecvwxg7Zcv3Khl0DBWRf2hbcCrvWFKgErH2fuW+Nuc' type='get' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:150)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:150)] Feb 24 09:46:18 c2s18b4cf0 debug #queue = 4 Feb 24 09:46:18 c2s18b4cf0 debug Handled 7 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <presence from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 5 Feb 24 09:46:18 c2s18b4cf0 debug #queue = 6 Feb 24 09:46:18 c2s18a4a10 debug #queue = 1 Feb 24 09:46:18 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s185fe30 debug #queue = 1 Feb 24 09:46:18 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:46:18 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for clafisc@test-test.org Feb 24 09:46:18 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for clafisc@test-test.org Feb 24 09:46:18 c2s18b4cf0 debug #queue = 7 Feb 24 09:46:18 test-test.org:presence debug broadcasted presence of 1 resources from clafisc@test-test.org to kafisc@test-test.org/phone Feb 24 09:46:18 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for kurfisc@test-test.org Feb 24 09:46:18 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for kurfisc@test-test.org Feb 24 09:46:18 c2s18b4cf0 debug #queue = 8 Feb 24 09:46:18 test-test.org:presence debug broadcasted presence of 1 resources from kurfisc@test-test.org to kafisc@test-test.org/phone Feb 24 09:46:18 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for homematic@test-test.org Feb 24 09:46:18 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for homematic@test-test.org Feb 24 09:46:18 test-test.org:presence debug broadcasted presence of 0 resources from homematic@test-test.org to kafisc@test-test.org/phone Feb 24 09:46:18 c2s18b4cf0 debug #queue = 9 Feb 24 09:46:18 test-test.org:presence debug outbound presence subscribe from kafisc@test-test.org for log@test-test.org Feb 24 09:46:18 rostermanager debug load_roster: asked for: kafisc@test-test.org Feb 24 09:46:18 c2s18b4cf0 debug #queue = 10 Feb 24 09:46:18 test-test.org:presence debug inbound presence subscribe from kafisc@test-test.org for log@test-test.org Feb 24 09:46:18 c2s18b4cf0 debug #queue = 11 Feb 24 09:46:18 rostermanager debug load_roster: asked for: log@test-test.org Feb 24 09:46:18 rostermanager debug load_roster: loading for offline user: log@test-test.org Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:46:18 c2s18b4cf0 debug #queue = 12 Feb 24 09:46:18 c2s18b4cf0 error Traceback[c2s]: /usr/lib/prosody/modules/mod_offline.lua:38: attempt to index local 'stanza' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_offline.lua:38: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? (tail call): ? /usr/lib/prosody/modules/mod_presence.lua:97: in function 'handle_normal_presence' /usr/lib/prosody/modules/mod_presence.lua:302: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? /usr/lib/prosody/core/stanza_router.lua:190: in function 'core_post_stanza' /usr/lib/prosody/core/stanza_router.lua:137: in function 'core_process_stanza' /usr/lib/prosody/modules/mod_c2s.lua:263: in function 'func' /usr/lib/prosody/util/async.lua:92: in function </usr/lib/prosody/util/async.lua:90> Feb 24 09:46:18 c2s18b4cf0 debug Handled 8 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='+cVTawl/ZW9M/k0kQnXxmA5qW4YhpRf/gAJskSTUvBYorZizzDQPxil4WCbj/ps6fLk' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 test-test.org:mam debug Archive query, id pgu0u22qi6 with anyone from the dawn of time until 2018-02-24T08:46:18Z) Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:46:18 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:46:18 c2s18b4cf0 debug #queue = 13 Feb 24 09:46:18 c2s18b4cf0 debug #queue = 14 Feb 24 09:46:18 test-test.org:mam debug Archive query pgu0u22qi6 completed Feb 24 09:46:18 c2s18b4cf0 debug #queue = 15 Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <active xmlns='urn:xmpp:csi:0'> Feb 24 09:46:18 c2s18b4cf0 debug Handled 9 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug Handled 10 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='l2Gr1r+2Y3ilG5AUIFa8A/G7Ssofh6//6LWrSj+HA8ITIiEEuXwEA/dMxdqBA6bkyzg' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 16 Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='4'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 14 Feb 24 09:46:18 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s18b4cf0 debug Handled 11 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='disco' type='result' to='kafisc@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 stanzarouter debug Discarding iq from c2s of type: result Feb 24 09:46:18 c2s18b4cf0 debug Handled 12 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <presence to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 konferenz.test-test.org:muc debug no occupant found for 1585i9kspcst5@konferenz.test-test.org/kafisc; creating new occupant object for kafisc@test-test.org/phone Feb 24 09:46:18 c2s18b4cf0 debug #queue = 15 Feb 24 09:46:18 c2s18b4cf0 debug #queue = 16 Feb 24 09:46:18 c2s18a4a10 debug #queue = 2 Feb 24 09:46:18 c2s185fe30 debug #queue = 2 Feb 24 09:46:18 c2s18b4cf0 debug #queue = 17 Feb 24 09:46:18 test-test.org:mam debug Not archiving stanza: <message id='6ad97b23-c546-4837-8873-383f70aa37d4' type='groupchat' to='kafisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org/kurfisc'> (type) Feb 24 09:46:18 c2s18b4cf0 debug #queue = 18 Feb 24 09:46:18 test-test.org:mam debug Not archiving stanza: <message type='groupchat' to='kafisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org'> (type) Feb 24 09:46:18 c2s18b4cf0 debug #queue = 19 Feb 24 09:46:18 c2s18b4cf0 debug Handled 13 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='939zLK52ilv7zYU0cRs8bANCTd3rN5gBtatOqlG3wtEcAAxuPtXJ1hpPf38EvyD3N9E' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 20 Feb 24 09:46:18 c2s18b4cf0 debug Handled 14 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='q3TZOtaH9cmMJskcWXAluURrqw2ZVdyA0VfiWD/ETlOvIp26iaHCaLsAG4BNxc3Zjfw' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 21 Feb 24 09:46:18 c2s18b4cf0 debug Handled 15 incoming stanzas Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <iq id='Iao2/9WT6ZHzPrqmF9cL4MnVJ2IjnSv7Lyy+WayM8cvmNfu2OX67T/1AauY7q4UETSo' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 22 Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='18'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 8 Feb 24 09:46:18 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='26'> Feb 24 09:46:18 c2s18b4cf0 debug #queue = 0 Feb 24 09:46:18 c2s15943c0 debug Handled 4 incoming stanzas Feb 24 09:46:18 c2s15943c0 debug Received[c2s]: <iq id='QHKmz6hS9QcduZteqszhudjIb1E+FqLnRMXHPmzopOvOgZzxFIeg/JeKqRIDrYAQsQE' type='get' to='konferenz.test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:18 c2s15943c0 debug #queue = 4 Feb 24 09:46:18 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2'> Feb 24 09:46:18 c2s15943c0 debug #queue = 2 Feb 24 09:46:18 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:46:18 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:46:18 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:46:18 c2s15943c0 debug Handled 5 incoming stanzas Feb 24 09:46:18 c2s15943c0 debug Received[c2s]: <iq id='u8qCMgPT0FkofDhfbHrVIw9YdKDeiSTxCJ/+ttqpUGFo8t9r4Pves10NkV2wDMzVRnk' type='get' from='clafisc@test-test.org/phone'> Feb 24 09:46:18 c2s15943c0 debug #queue = 3 Feb 24 09:46:18 c2s15943c0 debug Handled 6 incoming stanzas Feb 24 09:46:18 c2s15943c0 debug Received[c2s]: <iq id='rlKNZ/5WAbyCcRDVOTfYEj4dLWPsNbog+fAIEw8eumS01rqSD+Xyoe717gnB4GubD9M' type='get' from='clafisc@test-test.org/phone'> Feb 24 09:46:18 sql debug SQL transaction begin [function(mod_storage_sql.lua:150)] Feb 24 09:46:19 sql debug SQL transaction success [function(mod_storage_sql.lua:150)] Feb 24 09:46:19 c2s15943c0 debug #queue = 4 Feb 24 09:46:19 c2s15943c0 debug Handled 7 incoming stanzas Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <presence from='clafisc@test-test.org/phone'> Feb 24 09:46:19 c2s15943c0 debug #queue = 5 Feb 24 09:46:19 c2s15943c0 debug #queue = 6 Feb 24 09:46:19 c2s18a4a10 debug #queue = 3 Feb 24 09:46:19 c2s18b4cf0 debug #queue = 1 Feb 24 09:46:19 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:19 c2s185fe30 debug #queue = 3 Feb 24 09:46:19 test-test.org:presence debug outbound presence probe from clafisc@test-test.org for kafisc@test-test.org Feb 24 09:46:19 test-test.org:presence debug inbound presence probe from clafisc@test-test.org for kafisc@test-test.org Feb 24 09:46:19 c2s15943c0 debug #queue = 7 Feb 24 09:46:19 test-test.org:presence debug broadcasted presence of 1 resources from kafisc@test-test.org to clafisc@test-test.org/phone Feb 24 09:46:19 test-test.org:presence debug outbound presence probe from clafisc@test-test.org for kurfisc@test-test.org Feb 24 09:46:19 test-test.org:presence debug inbound presence probe from clafisc@test-test.org for kurfisc@test-test.org Feb 24 09:46:19 c2s15943c0 debug #queue = 8 Feb 24 09:46:19 test-test.org:presence debug broadcasted presence of 1 resources from kurfisc@test-test.org to clafisc@test-test.org/phone Feb 24 09:46:19 c2s15943c0 debug #queue = 9 Feb 24 09:46:19 test-test.org:presence debug outbound presence subscribe from clafisc@test-test.org for homematic@test-test.org Feb 24 09:46:19 rostermanager debug load_roster: asked for: clafisc@test-test.org Feb 24 09:46:19 c2s15943c0 debug #queue = 10 Feb 24 09:46:19 c2s18a4a10 debug #queue = 4 Feb 24 09:46:19 test-test.org:presence debug inbound presence subscribe from clafisc@test-test.org for homematic@test-test.org Feb 24 09:46:19 c2s15943c0 debug #queue = 11 Feb 24 09:46:19 c2s18a4a10 debug #queue = 5 Feb 24 09:46:19 rostermanager debug load_roster: asked for: homematic@test-test.org Feb 24 09:46:19 rostermanager debug load_roster: loading for offline user: homematic@test-test.org Feb 24 09:46:19 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:19 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:19 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:46:19 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:46:19 sql debug SQL transaction begin [function(mod_storage_sql.lua:367)] Feb 24 09:46:19 sql debug SQL transaction success [function(mod_storage_sql.lua:367)] Feb 24 09:46:19 c2s15943c0 debug Handled 8 incoming stanzas Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <iq id='XQHWOzVCqlnim7HwycjtYe2G9RiMtKNeWtn2d6aODRn9C3RtoJau3TRrAprOPv7xp4k' type='set' from='clafisc@test-test.org/phone'> Feb 24 09:46:19 test-test.org:mam debug Archive query, id gk454i452l with anyone from the dawn of time until 2018-02-24T08:46:12Z) Feb 24 09:46:19 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:46:19 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:46:19 c2s15943c0 debug #queue = 12 Feb 24 09:46:19 c2s15943c0 debug #queue = 13 Feb 24 09:46:19 test-test.org:mam debug Archive query gk454i452l completed Feb 24 09:46:19 c2s15943c0 debug #queue = 14 Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <inactive xmlns='urn:xmpp:csi:0'> Feb 24 09:46:19 c2s15943c0 debug Handled 9 incoming stanzas Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/clafisc' from='clafisc@test-test.org/phone'> Feb 24 09:46:19 c2s15943c0 debug Handled 10 incoming stanzas Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <iq id='EFOfrIh+BDZV2BL8AdbQ45iIi0y8Q/w+DmmSD1v820PgtQ9zhraPGMj89w5UvAbkUr4' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:19 c2s15943c0 debug #queue = 15 Feb 24 09:46:19 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:19 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='4'> Feb 24 09:46:19 c2s15943c0 debug #queue = 13 Feb 24 09:46:19 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:46:19 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:46:19 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:46:19 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='27'> Feb 24 09:46:19 c2s18b4cf0 debug #queue = 0 Feb 24 09:46:19 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='23'> Feb 24 09:46:19 c2s185fe30 debug #queue = 2 Feb 24 09:46:19 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:46:19 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:46:19 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:46:19 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='25'> Feb 24 09:46:19 c2s185fe30 debug #queue = 0 Feb 24 09:46:19 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='24'> Feb 24 09:46:19 c2s18a4a10 debug #queue = 4 Feb 24 09:46:19 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:46:19 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:46:19 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:46:19 c2s15943c0 debug Handled 11 incoming stanzas Feb 24 09:46:19 c2s15943c0 debug Received[c2s]: <iq id='disco' type='result' to='clafisc@test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:19 stanzarouter debug Discarding iq from c2s of type: result Feb 24 09:46:19 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='28'> Feb 24 09:46:19 c2s18a4a10 debug #queue = 0 Feb 24 09:46:22 c2s15943c0 debug Handled 12 incoming stanzas Feb 24 09:46:22 c2s15943c0 debug Received[c2s]: <presence to='1585i9kspcst5@konferenz.test-test.org/clafisc' from='clafisc@test-test.org/phone'> Feb 24 09:46:22 c2s15943c0 debug #queue = 14 Feb 24 09:46:22 c2s15943c0 debug #queue = 15 Feb 24 09:46:22 c2s185fe30 debug #queue = 1 Feb 24 09:46:22 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:46:22 c2s18b4cf0 debug #queue = 1 Feb 24 09:46:22 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:46:22 c2s18a4a10 debug #queue = 1 Feb 24 09:46:22 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:46:22 c2s15943c0 debug #queue = 16 Feb 24 09:46:22 test-test.org:mam debug Not archiving stanza: <message type='groupchat' to='clafisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org'> (type) Feb 24 09:46:22 c2s15943c0 debug #queue = 17 Feb 24 09:46:22 c2s15943c0 debug Handled 13 incoming stanzas Feb 24 09:46:22 c2s15943c0 debug Received[c2s]: <iq id='RhnJhC9BbvxTUNixJoBDYnnbtYLaofwMnNbwKxyIbS1GsldLCqY2nBzKZLjdrVhcNIw' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:22 c2s15943c0 debug #queue = 18 Feb 24 09:46:22 c2s15943c0 debug Handled 14 incoming stanzas Feb 24 09:46:22 c2s15943c0 debug Received[c2s]: <iq id='NxUB/wTId3r9EKV8mAdjRzrfdKUnGXK5qAbjUidbdrNttQ5I/5w85cDczKHPgeIdNhg' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:22 c2s15943c0 debug #queue = 19 Feb 24 09:46:22 c2s15943c0 debug Handled 15 incoming stanzas Feb 24 09:46:22 c2s15943c0 debug Received[c2s]: <iq id='XLXjqZfRfGLYoqh6doXy4mK7lFD8dJHMuPvwPpU6FhI1FffaPtp2AfsPypJABdRE9/w' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='clafisc@test-test.org/phone'> Feb 24 09:46:22 c2s15943c0 debug #queue = 20 Feb 24 09:46:22 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='17'> Feb 24 09:46:22 c2s15943c0 debug #queue = 7 Feb 24 09:46:22 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:46:22 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:46:22 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:46:22 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:46:22 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:46:22 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:46:22 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:46:22 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:46:22 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:46:23 c2s18b4cf0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='28'> Feb 24 09:46:23 c2s18b4cf0 debug #queue = 0 Feb 24 09:46:23 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='29'> Feb 24 09:46:23 c2s18a4a10 debug #queue = 0 Feb 24 09:46:23 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='26'> Feb 24 09:46:23 c2s185fe30 debug #queue = 0 Feb 24 09:46:23 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='24'> Feb 24 09:46:23 c2s15943c0 debug #queue = 0 Feb 24 09:46:31 socket debug server.lua: accepted new client connection from 95.208.189.211:49534 to 5280 Feb 24 09:46:31 http.server debug Firing event: POST test-test.org/msg/kafisc@test-test.org Feb 24 09:46:31 test-test.org:auth_internal_hashed debug test password for user 'homematic' Feb 24 09:46:31 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:31 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:31 test-test.org:mod_post_msg debug Authed as homematic@test-test.org Feb 24 09:46:31 test-test.org:mod_post_msg debug Sending <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'><body>Zeichenlaenge angepasst</body></message> Feb 24 09:46:31 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:31 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:31 test-test.org:mam debug kafisc's rule for homematic@test-test.org is nil Feb 24 09:46:31 test-test.org:mam debug kafisc's default rule is true Feb 24 09:46:31 test-test.org:mam debug Archiving stanza: <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'> Feb 24 09:46:31 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:31 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:31 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:31 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:31 socket debug server.lua: client 95.208.189.211:49534 read error: closed Feb 24 09:46:31 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:46:35 socket debug server.lua: accepted new client connection from 95.208.189.211:49554 to 5280 Feb 24 09:46:35 http.server debug Firing event: POST test-test.org/msg/kafisc@test-test.org Feb 24 09:46:35 test-test.org:auth_internal_hashed debug test password for user 'homematic' Feb 24 09:46:35 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:35 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:35 test-test.org:mod_post_msg debug Authed as homematic@test-test.org Feb 24 09:46:35 test-test.org:mod_post_msg debug Sending <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'><body>Zeichenlaenge angepasst</body></message> Feb 24 09:46:35 test-test.org:mam debug kafisc's rule for homematic@test-test.org is nil Feb 24 09:46:35 test-test.org:mam debug kafisc's default rule is true Feb 24 09:46:35 test-test.org:mam debug Archiving stanza: <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'> Feb 24 09:46:35 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:35 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:35 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:35 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:35 socket debug server.lua: client 95.208.189.211:49554 read error: closed Feb 24 09:46:35 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:46:36 socket debug server.lua: accepted new client connection from 95.208.189.211:49568 to 5280 Feb 24 09:46:36 http.server debug Firing event: POST test-test.org/msg/kafisc@test-test.org Feb 24 09:46:36 test-test.org:auth_internal_hashed debug test password for user 'homematic' Feb 24 09:46:36 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:46:36 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:46:36 test-test.org:mod_post_msg debug Authed as homematic@test-test.org Feb 24 09:46:36 test-test.org:mod_post_msg debug Sending <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'><body>Zeichenlaenge angepasst</body></message> Feb 24 09:46:36 test-test.org:mam debug kafisc's rule for homematic@test-test.org is nil Feb 24 09:46:36 test-test.org:mam debug kafisc's default rule is true Feb 24 09:46:36 test-test.org:mam debug Archiving stanza: <message type='chat' to='kafisc@test-test.org' from='homematic@test-test.org'> Feb 24 09:46:36 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:36 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:36 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:46:36 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:46:36 socket debug server.lua: client 95.208.189.211:49568 read error: closed Feb 24 09:46:36 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:47:02 c2s18b4cf0 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:47:02 test-test.org:smacks debug Received ack request, acking for 15 Feb 24 09:47:31 c2s18b4cf0 debug Handled 16 incoming stanzas Feb 24 09:47:31 c2s18b4cf0 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:47:31 konferenz.test-test.org:muc debug session kafisc@test-test.org/phone is leaving occupant 1585i9kspcst5@konferenz.test-test.org/kafisc Feb 24 09:47:31 c2s18a4a10 debug #queue = 1 Feb 24 09:47:31 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:47:31 c2s15943c0 debug #queue = 1 Feb 24 09:47:31 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:47:31 c2s185fe30 debug #queue = 1 Feb 24 09:47:31 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:47:31 c2s18b4cf0 debug #queue = 1 Feb 24 09:47:31 c2s18b4cf0 debug Queuing <r> (in a moment) Feb 24 09:47:31 c2s18b4cf0 debug Handled 17 incoming stanzas Feb 24 09:47:31 c2s18b4cf0 debug Received[c2s]: <presence from='kafisc@test-test.org/phone' type='unavailable'> Feb 24 09:47:31 c2s18b4cf0 debug #queue = 2 Feb 24 09:47:31 c2s15943c0 debug #queue = 2 Feb 24 09:47:31 c2s18a4a10 debug #queue = 2 Feb 24 09:47:31 c2s185fe30 debug #queue = 2 Feb 24 09:47:31 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:47:31 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:47:31 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:47:31 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:47:31 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:47:31 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:47:31 c2s18b4cf0 debug Sending <r> (inside timer, before send) Feb 24 09:47:31 c2s18b4cf0 debug Sending <r> (inside timer, after send) Feb 24 09:47:32 c2s18b4cf0 debug Received </stream:stream> Feb 24 09:47:32 c2s18b4cf0 debug c2s stream for kafisc@test-test.org/phone closed: session closed Feb 24 09:47:32 c2s18b4cf0 debug Destroying session for kafisc@test-test.org/phone (kafisc@test-test.org) Feb 24 09:47:32 c2s18b4cf0 warn Destroying session with 2 unacked stanzas Feb 24 09:47:32 c2s18b4cf0 debug Received[c2s]: <presence type='error' to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:47:32 stanzarouter debug Discarding unhandled error presence (cancel, recipient-unavailable) from c2s: <presence type='error' to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:47:32 sessionmanager debug All resources of kafisc are now offline Feb 24 09:47:32 c2s18b4cf0 info Client disconnected: connection closed Feb 24 09:47:32 c2s18b4cf0 debug Destroying session for (unknown) ((unknown)@(unknown)) Feb 24 09:47:32 socket debug server.lua: closed client handler and removed socket from list Feb 24 09:47:32 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='31'> Feb 24 09:47:32 c2s18a4a10 debug #queue = 0 Feb 24 09:47:32 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='26'> Feb 24 09:47:32 c2s15943c0 debug #queue = 0 Feb 24 09:47:32 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='28'> Feb 24 09:47:32 c2s185fe30 debug #queue = 0 Feb 24 09:47:33 socket debug server.lua: accepted new client connection from 95.208.189.211:42255 to 5222 Feb 24 09:47:33 c2s1955000 info Client connected Feb 24 09:47:33 c2s1955000 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:47:33 c2s1955000 debug Sent reply <stream:stream> to client Feb 24 09:47:33 c2s1955000 debug Not offering authentication on insecure connection Feb 24 09:47:33 c2s1955000 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> Feb 24 09:47:33 socket debug server.lua: we need to do tls, but delaying until send buffer empty Feb 24 09:47:33 c2s1955000 debug TLS negotiation started for c2s_unauthed... Feb 24 09:47:33 socket debug server.lua: attempting to start tls on tcp{client}: 0x1952010 Feb 24 09:47:33 socket debug server.lua: ssl handshake done Feb 24 09:47:33 c2s1955000 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:47:33 c2s1955000 debug Sent reply <stream:stream> to client Feb 24 09:47:33 c2s1955000 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) Feb 24 09:47:33 c2s1955000 debug Offering mechanism PLAIN Feb 24 09:47:33 c2s1955000 debug Offering mechanism SCRAM-SHA-1 Feb 24 09:47:33 c2s1955000 debug Offering mechanism SCRAM-SHA-1-PLUS Feb 24 09:47:33 c2s1955000 debug Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:47:33 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:47:33 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:47:33 test-test.org:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1ZVHczTFo3Uk9RemFjWXp4ekpmSEI5OXRFT2Z2bG05UGtvbURrQTVEVTU5aDNiNjRLQmRibmRpUXhwRUpTK3UrWU1UcGxabXZrSW95UjdsK2dZS2FQNFhJWjBsSFVWbm1ZaUxmelBXU2YrVTZNZmc5NFphdXptWXNDL2cya2ZNM1pIa2Fvd2Y2NGZjZmY4LTI5MjYtNGUyZi1hNjJkLWZiOWE0NWZmOTBiMixzPU1USmpZV1JpWVdVdE1qUXhPQzAwTkdOaExXRm1NelV0T1dFelpqYzBabVkwWWpnMixpPTQwOTY=</challenge> Feb 24 09:47:33 c2s1955000 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> Feb 24 09:47:33 c2s1955000 info Authenticated as kafisc@test-test.org Feb 24 09:47:33 test-test.org:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1sTm9XK3ZNaWUrczkyU0VuMi9lK1FLRHVzSGs9</success> Feb 24 09:47:33 c2s1955000 debug Client sent opening <stream:stream> to test-test.org Feb 24 09:47:33 c2s1955000 debug Sent reply <stream:stream> to client Feb 24 09:47:33 c2s1955000 debug Received[c2s_unbound]: <iq id='fSHlYov2vIIN9N+EpUvXtn6VX4ElGeUQeBWJiIVG3cFSZqOpWStlz460KsnkdjTEVas' type='set'> Feb 24 09:47:33 rostermanager debug load_roster: asked for: kafisc@test-test.org Feb 24 09:47:33 rostermanager debug load_roster: loading for new user: kafisc@test-test.org Feb 24 09:47:33 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:47:33 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:47:33 mod_admin_web debug Added client kafisc@test-test.org/phone Feb 24 09:47:33 c2s1955000 debug Resource bound: kafisc@test-test.org/phone Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <enable xmlns='urn:xmpp:sm:3' resume='true'> Feb 24 09:47:33 test-test.org:smacks debug Enabling stream management Feb 24 09:47:33 c2s1955000 debug Handled 1 incoming stanzas Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <iq id='qHFKWCYs/Vk+9qKMQDbGw5e2KgwG9tuEJlAPJ9pi7PoU491J7agh7r6iBL/6fKHY9K0' type='get' to='kafisc@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:33 c2s1955000 debug #queue = 1 Feb 24 09:47:33 c2s1955000 debug Queuing <r> (in a moment) Feb 24 09:47:33 c2s1955000 debug Handled 2 incoming stanzas Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <iq id='tnOfSHe+ZCDbZiM70lF7T37/4UkFz77WwJrNW7JZF0Gv50LQ/BSiVsgt/KkA2Vbeaw8' type='get' to='test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:33 c2s1955000 debug #queue = 2 Feb 24 09:47:33 c2s1955000 debug Sending <r> (inside timer, before send) Feb 24 09:47:33 c2s1955000 debug Sending <r> (inside timer, after send) Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Feb 24 09:47:33 test-test.org:smacks debug Received ack request, acking for 2 Feb 24 09:47:33 c2s1955000 debug Handled 3 incoming stanzas Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <iq id='XPAHwo7puS2Q6IXgjJBs3Y/V15CX68+293f7DgAhslkVb7p05XMid0LFPn6gU2hG6l0' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:47:33 test-test.org:carbons debug kafisc@test-test.org/phone enabled carbons Feb 24 09:47:33 c2s1955000 debug #queue = 3 Feb 24 09:47:33 c2s1955000 debug Handled 4 incoming stanzas Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <iq id='kZbUZUz6A6s9+p0bW7ByowV97q+mDeMVpp+59s8P9MMkOYTWM+tPS1Akygg4AZ7Rmig' type='get' to='kafisc@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:33 c2s1955000 debug #queue = 4 Feb 24 09:47:33 test-test.org:pep debug Item 'eu.siacs.conversations.axolotl.bundles:264800424' not found Feb 24 09:47:33 c2s1955000 debug Handled 5 incoming stanzas Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <iq id='oRYZFYtNlPmLLGGEXlhRDy16TH2IusDvUs8oG12hxepm/b/Hn6yyCykqR8IjlHFf404' type='get' to='konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:33 c2s1955000 debug #queue = 5 Feb 24 09:47:33 c2s1955000 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='2'> Feb 24 09:47:33 c2s1955000 debug #queue = 3 Feb 24 09:47:33 c2s1955000 debug Queuing <r> (in a moment) Feb 24 09:47:33 c2s1955000 debug Sending <r> (inside timer, before send) Feb 24 09:47:33 c2s1955000 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s1955000 debug Handled 6 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='+hho56HIAzZTuEYt/RBVUI1WvxAjeHdmF9ExsObX9y9uQ57ep+D7HkV1Q6U1AHB3xpE' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 4 Feb 24 09:47:34 c2s1955000 debug Handled 7 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='sSz5cj1OQQhqQn1fXve9zI13cYUgL51X3p5hF7hvjI5UzDj/Si8XsipFiuwwE1dtAA0' type='get' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 5 Feb 24 09:47:34 c2s1955000 debug Handled 8 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='aF2T7QA+kLNivVh1v5HqrQ2QooUksIOV4TR5g/Np0CDGx0OcmgZQ8dRyYdjyCFwDMhA' type='get' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 sql debug SQL transaction begin [function(mod_storage_sql.lua:150)] Feb 24 09:47:34 sql debug SQL transaction success [function(mod_storage_sql.lua:150)] Feb 24 09:47:34 c2s1955000 debug #queue = 6 Feb 24 09:47:34 c2s1955000 debug Handled 9 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <presence from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 7 Feb 24 09:47:34 c2s15943c0 debug #queue = 1 Feb 24 09:47:34 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:47:34 c2s18a4a10 debug #queue = 1 Feb 24 09:47:34 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:47:34 c2s185fe30 debug #queue = 1 Feb 24 09:47:34 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:47:34 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for clafisc@test-test.org Feb 24 09:47:34 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for clafisc@test-test.org Feb 24 09:47:34 c2s1955000 debug #queue = 8 Feb 24 09:47:34 c2s1955000 debug #queue = 9 Feb 24 09:47:34 test-test.org:presence debug broadcasted presence of 2 resources from clafisc@test-test.org to kafisc@test-test.org/phone Feb 24 09:47:34 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for kurfisc@test-test.org Feb 24 09:47:34 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for kurfisc@test-test.org Feb 24 09:47:34 c2s1955000 debug #queue = 10 Feb 24 09:47:34 test-test.org:presence debug broadcasted presence of 1 resources from kurfisc@test-test.org to kafisc@test-test.org/phone Feb 24 09:47:34 test-test.org:presence debug outbound presence probe from kafisc@test-test.org for homematic@test-test.org Feb 24 09:47:34 test-test.org:presence debug inbound presence probe from kafisc@test-test.org for homematic@test-test.org Feb 24 09:47:34 test-test.org:presence debug broadcasted presence of 0 resources from homematic@test-test.org to kafisc@test-test.org/phone Feb 24 09:47:34 c2s1955000 debug #queue = 11 Feb 24 09:47:34 test-test.org:presence debug outbound presence subscribe from kafisc@test-test.org for log@test-test.org Feb 24 09:47:34 rostermanager debug load_roster: asked for: kafisc@test-test.org Feb 24 09:47:34 c2s1955000 debug #queue = 12 Feb 24 09:47:34 test-test.org:presence debug inbound presence subscribe from kafisc@test-test.org for log@test-test.org Feb 24 09:47:34 c2s1955000 debug #queue = 13 Feb 24 09:47:34 rostermanager debug load_roster: asked for: log@test-test.org Feb 24 09:47:34 rostermanager debug load_roster: loading for offline user: log@test-test.org Feb 24 09:47:34 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:47:34 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:47:34 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:47:34 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:47:34 c2s1955000 debug #queue = 14 Feb 24 09:47:34 c2s1955000 error Traceback[c2s]: /usr/lib/prosody/modules/mod_offline.lua:38: attempt to index local 'stanza' (a nil value) stack traceback: /usr/lib/prosody/modules/mod_offline.lua:38: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? (tail call): ? /usr/lib/prosody/modules/mod_presence.lua:97: in function 'handle_normal_presence' /usr/lib/prosody/modules/mod_presence.lua:302: in function '?' /usr/lib/prosody/util/events.lua:78: in function </usr/lib/prosody/util/events.lua:74> (tail call): ? /usr/lib/prosody/core/stanza_router.lua:190: in function 'core_post_stanza' /usr/lib/prosody/core/stanza_router.lua:137: in function 'core_process_stanza' /usr/lib/prosody/modules/mod_c2s.lua:263: in function 'func' /usr/lib/prosody/util/async.lua:92: in function </usr/lib/prosody/util/async.lua:90> Feb 24 09:47:34 c2s1955000 debug Handled 10 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='F9nlixXTkE324g8ZKNDXMS/dvwgMaDN3N+J9/KzDTimghIxPAuqhDY2Dr3ehURhmAec' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 test-test.org:mam debug Archive query, id 98lnevpc3e with anyone from the dawn of time until 2018-02-24T08:47:33Z) Feb 24 09:47:34 sql debug SQL transaction begin [function(mod_storage_sql.lua:319)] Feb 24 09:47:34 sql debug SQL transaction success [function(mod_storage_sql.lua:319)] Feb 24 09:47:34 c2s1955000 debug #queue = 15 Feb 24 09:47:34 c2s1955000 debug #queue = 16 Feb 24 09:47:34 c2s1955000 debug #queue = 17 Feb 24 09:47:34 test-test.org:mam debug Archive query 98lnevpc3e completed Feb 24 09:47:34 c2s1955000 debug #queue = 18 Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <active xmlns='urn:xmpp:csi:0'> Feb 24 09:47:34 c2s1955000 debug Handled 11 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <presence type='unavailable' to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug Handled 12 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='abmEcNv6cgseg9shDP57ZjZ8uHRovZ3RfTJcSSqIVprJpjlArI5Qs/Z+I6cDQohzohE' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 19 Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='5'> Feb 24 09:47:34 c2s1955000 debug #queue = 16 Feb 24 09:47:34 c2s1955000 debug Queuing <r> (in a moment) Feb 24 09:47:34 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s1955000 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s1955000 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s1955000 debug Handled 13 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='8l9bfPz8iLa34oUSLZF30A9moZIU+kiQ17TSmd3xhoXMBma+cgTIuwRHtOVaMsdoGN4' type='get' to='kafisc@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 17 Feb 24 09:47:34 test-test.org:pep debug Item 'eu.siacs.conversations.axolotl.devicelist' not found Feb 24 09:47:34 c2s1955000 debug Handled 14 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <presence to='1585i9kspcst5@konferenz.test-test.org/kafisc' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 konferenz.test-test.org:muc debug no occupant found for 1585i9kspcst5@konferenz.test-test.org/kafisc; creating new occupant object for kafisc@test-test.org/phone Feb 24 09:47:34 c2s1955000 debug #queue = 18 Feb 24 09:47:34 c2s1955000 debug #queue = 19 Feb 24 09:47:34 c2s18a4a10 debug #queue = 2 Feb 24 09:47:34 c2s15943c0 debug #queue = 2 Feb 24 09:47:34 c2s185fe30 debug #queue = 2 Feb 24 09:47:34 c2s1955000 debug #queue = 20 Feb 24 09:47:34 test-test.org:mam debug Not archiving stanza: <message id='6ad97b23-c546-4837-8873-383f70aa37d4' type='groupchat' to='kafisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org/kurfisc'> (type) Feb 24 09:47:34 c2s1955000 debug #queue = 21 Feb 24 09:47:34 test-test.org:mam debug Not archiving stanza: <message type='groupchat' to='kafisc@test-test.org/phone' from='1585i9kspcst5@konferenz.test-test.org'> (type) Feb 24 09:47:34 c2s1955000 debug #queue = 22 Feb 24 09:47:34 c2s1955000 debug Handled 15 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='NqJ0CeZ5vUTdzej1YekYFBFe4Qs/Dgj4f+FLlBmT7dQniRnsBCa5mf4JCGOxnZ7t5EQ' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 23 Feb 24 09:47:34 c2s1955000 debug Handled 16 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='LXpFvbOGsMoC8DVFTP/65aLlMl0K0Dpw/XPaCfi7gxsoT2rUBmELdx//M1idwtJtNUE' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 24 Feb 24 09:47:34 c2s1955000 debug Handled 17 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='xlN6Ms70x796xHIc/G5UJ2j1zjguqw82EZcKdU5kakgd9gL5Y4xnCUopUkm7gKhrxtw' type='get' to='1585i9kspcst5@konferenz.test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 25 Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='21'> Feb 24 09:47:34 c2s1955000 debug #queue = 9 Feb 24 09:47:34 c2s1955000 debug Queuing <r> (in a moment) Feb 24 09:47:34 c2s1955000 debug Handled 18 incoming stanzas Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <iq id='KwhjQ+6tJ2iqqj14/UMF/Ai9wVnpBtaOyTCg+zuwb/KxuG9e4gU36cBncW23lq/9XVc' type='set' from='kafisc@test-test.org/phone'> Feb 24 09:47:34 c2s1955000 debug #queue = 10 Feb 24 09:47:34 test-test.org:mam debug Not archiving stanza: <message type='headline' to='kafisc@test-test.org/phone' from='kafisc@test-test.org'> (type) Feb 24 09:47:34 c2s1955000 debug #queue = 11 Feb 24 09:47:34 c2s1955000 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s1955000 debug Sending <r> (inside timer, after send) Feb 24 09:47:34 c2s1955000 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='32'> Feb 24 09:47:34 c2s1955000 debug #queue = 0 Feb 24 09:47:34 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='27'> Feb 24 09:47:34 c2s15943c0 debug #queue = 1 Feb 24 09:47:34 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:47:34 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:47:34 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:47:35 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='28'> Feb 24 09:47:35 c2s15943c0 debug #queue = 0 Feb 24 09:47:35 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='32'> Feb 24 09:47:35 c2s18a4a10 debug #queue = 1 Feb 24 09:47:35 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:47:35 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:47:35 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:47:35 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='33'> Feb 24 09:47:35 c2s18a4a10 debug #queue = 0 Feb 24 09:47:35 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='29'> Feb 24 09:47:35 c2s185fe30 debug #queue = 1 Feb 24 09:47:35 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:47:35 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:47:35 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:47:35 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='30'> Feb 24 09:47:35 c2s185fe30 debug #queue = 0 Feb 24 09:47:46 c2s1955000 debug Handled 19 incoming stanzas Feb 24 09:47:46 c2s1955000 debug Received[c2s]: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:46 c2s1955000 debug Not archiving stanza: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> (hint) Feb 24 09:47:46 test-test.org:mam debug Not archiving stanza: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> (hint) Feb 24 09:47:46 test-test.org:carbons debug Skip carbons for offline user Feb 24 09:47:46 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:47:46 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:47:46 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:47:46 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:47:48 c2s1955000 debug Handled 20 incoming stanzas Feb 24 09:47:48 c2s1955000 debug Received[c2s]: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> Feb 24 09:47:48 c2s1955000 debug Not archiving stanza: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> (hint) Feb 24 09:47:48 test-test.org:mam debug Not archiving stanza: <message type='chat' to='homematic@test-test.org' from='kafisc@test-test.org/phone'> (hint) Feb 24 09:47:48 test-test.org:carbons debug Skip carbons for offline user Feb 24 09:47:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:57)] Feb 24 09:47:48 sql debug SQL transaction success [function(mod_storage_sql.lua:57)] Feb 24 09:47:48 sql debug SQL transaction begin [function(mod_storage_sql.lua:228)] Feb 24 09:47:48 sql debug SQL transaction success [function(mod_storage_sql.lua:228)] Feb 24 09:48:19 c2s1955000 debug Handled 21 incoming stanzas Feb 24 09:48:19 c2s1955000 debug Received[c2s]: <presence from='kafisc@test-test.org/phone'> Feb 24 09:48:19 c2s1955000 debug #queue = 1 Feb 24 09:48:19 c2s1955000 debug Queuing <r> (in a moment) Feb 24 09:48:19 c2s15943c0 debug #queue = 1 Feb 24 09:48:19 c2s15943c0 debug Queuing <r> (in a moment) Feb 24 09:48:19 c2s18a4a10 debug #queue = 1 Feb 24 09:48:19 c2s18a4a10 debug Queuing <r> (in a moment) Feb 24 09:48:19 c2s185fe30 debug #queue = 1 Feb 24 09:48:19 c2s185fe30 debug Queuing <r> (in a moment) Feb 24 09:48:19 c2s1955000 debug Received[c2s]: <inactive xmlns='urn:xmpp:csi:0'> Feb 24 09:48:19 c2s1955000 debug Sending <r> (inside timer, before send) Feb 24 09:48:19 c2s1955000 debug Sending <r> (inside timer, after send) Feb 24 09:48:19 c2s15943c0 debug Sending <r> (inside timer, before send) Feb 24 09:48:19 c2s15943c0 debug Sending <r> (inside timer, after send) Feb 24 09:48:19 c2s18a4a10 debug Sending <r> (inside timer, before send) Feb 24 09:48:19 c2s18a4a10 debug Sending <r> (inside timer, after send) Feb 24 09:48:19 c2s185fe30 debug Sending <r> (inside timer, before send) Feb 24 09:48:19 c2s185fe30 debug Sending <r> (inside timer, after send) Feb 24 09:48:19 c2s1955000 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='33'> Feb 24 09:48:19 c2s1955000 debug #queue = 0 Feb 24 09:48:19 c2s15943c0 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='29'> Feb 24 09:48:19 c2s15943c0 debug #queue = 0 Feb 24 09:48:19 c2s185fe30 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='31'> Feb 24 09:48:19 c2s185fe30 debug #queue = 0 Feb 24 09:48:27 c2s18a4a10 debug Received[c2s]: <a xmlns='urn:xmpp:sm:3' h='34'> Feb 24 09:48:27 c2s18a4a10 debug #queue = 0

The log@test-test.org user appears to have something corrupted in their offline store. Please check what is there. A query with something like WHERE host = 'test-test.org' AND user = 'log' AND store = 'offline' should return the relevant rows. Check that the 'value' column contains valid XML data.

• owner Zash
• tags Status-NeedInfo

Thank you very much. Deleting all "offline" entries resolved the issue.

How will we know where they came from?

No way to fix the root cause without knowing what those messages were or where they came from.

• tags Status-CantFix