Sometimes message output order different

[jamieabc]

rtail is a fancy tool, it let's viewing log much easier than before. As I use it through tail command, some weird situation occurs:

1. Sometimes rtail receives log with different order as tail. For example, output of tail is aaaaa bbbbb ccccc but output of rtail is aaaaa ccccc bbbbb
2. Sometimes rtail dropped log messages. For example, output of tail is aaaaa bbbbb ccccc but output of rtail is aaaaa ccccc

Are these bugs or any way I can avoid this?

[kilianc]

@jamieabc this is the nature of UDP, you may drop messages and order is not guaranteed. The UI sorts by timestamps so I suspect there may be something we can do about it.

Timestamps are creates by the cli client as soon as a new line comes in, so the order should be honored no matter what.

Do you have the specific lines or a way for me to replicate? OS / Browser etc?

[jamieabc]

Currently we use rtail to show mysql slow log using following command tail -f mysql-slow-.log | rtail. In some cases, mysql will output 50+ messages in 1 second, for this situation, we will see message order changed or dropped. I think other circumstances that generates messages 50+ per second will have same effect.

[kilianc]

thanks for giving little more context. I will run a test myself with high throughput and see if I can manage to reproduce it.

• Are you guys running latest ?
• is rtail-server local, same LAN, or WAN ?

[jamieabc]

Previous running version is 0.2.0, I have tested latest version (0.2.1) and message order changed/dropped still happens. Currently I run `rtail-server' and 'rtail' both on same local computer. I am not sure if it helps, looks like 150+ messages popped in a second.

Log from mysql-slow.log using command tail -f mysql-slow.log | rtail: Time: 150718 15:35:24

User@Host: admin[admin] @ [192.168.101.29]

# Thread_id: 424664  Schema: vpon_dsp  QC_hit: No
# Query_time: 0.000473  Lock_time: 0.000191  Rows_sent: 0  Rows_examined: 1
SET timestamp=1437204924;
UPDATE `delayed_jobs` SET `delayed_jobs`.`locked_at` = '2015-07-18 07:35:24', `delayed_jobs`.`locked_by` = 'delayed_job host:dsp-office-staging pid:37' WHERE ((run_at <= '2015-07-18 07:35:24' AND (locked_at IS NULL OR locked_at < '2015-07-18 03:35:24') OR locked_by = 'delayed_job host:dsp-office-staging pid:37') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1;
# Time: 150718 15:35:25

Log seen from web: Time: 150718 15:35:24

User@Host: admin[admin] @ [192.168.101.29]

# Thread_id: 424664  Schema: vpon_dsp  QC_hit: No
# Query_time: 0.000473  Lock_time: 0.000191  Rows_sent: 0  Rows_examined: 1
SET timestamp=1437204924;
# Time: 150718 15:35:25

As you can see, the UPDATE log is disappeared.