Let’s Chat a Bit Non-Tech
It’s been half a year since the last update, and it’s rare I feel like writing something. Though I planned to write this morning, I got distracted halfway through by something else. The company, in collaboration with an insurance company, launched a medical insurance policy and asked us to buy it for our parents, so I spent half a day reviewing the terms. I also remembered the good medical insurance I bought through Alipay a couple of years ago; however, I’m not quite sure about its terms, so I checked, found a lot of pitfalls, and prepared myself for a dispute during claims.
After studying the company’s insurance policy, I decided to cancel the Alipay one. Especially the health declaration part: If there has been any hospitalization behavior in the past two years, it doesn’t meet the health declaration requirements.
I even called my parents, and they can’t remember if they were hospitalized a few years ago or not. Anyway, I don’t feel assured. In the afternoon, I tried to contact Alipay, but couldn’t find their customer service for ages.
Everyone should also pay more attention.
Background
I’m responsible for a backend service that receives client requests and simultaneously writes to the database. For instance, creating a task, where the creation time in the code is directly a new Date, then written to the database. However, when I checked the creation time using my client software, there was a 13-hour difference.
Of course, the client software shows a 13-hour gap, but when I look at it on the web interface, there’s no problem.
For example, the current time is 21:02, I create a task on the interface, and then use the mysql client SQLyog to check the task’s creation time:
Ftask_id Fcreate_time
-------- --------------------- 4121 2021-06-19 08:02:36 Hey, how come it’s 8 o’clock? Comparing to now, there’s a 21 – 8 = 13-hour difference.
This time zone issue generally relates to some mysql variables, for example, we checked like this,
SHOW VARIABLES LIKE '%zone%'
Variable_name Value ---------------- --------system_time_zone CST time_zone SYSTEM This CST and system, though not clearly understood, seem a bit problematic. So I looked it up on certain search engines, and changing some settings typically solves it.
But on this mysql instance, we’re not the only ones with a database—there are dozens. So, I didn’t dare change the database settings recklessly, just in case someone configured it that way deliberately.
I then asked a colleague who also has another database on this instance, but oddly, when he used the program to create new Date, the time written was correct.
We’re all in the same team, using the same mybatis framework. It’s unlikely that it works for him but not for me.
I decided to find out the reason.
Obviously, such a blatant bug wasn’t noticed before? Well, no, because I checked through the web interface, and it was correct.
/>
Although it’s just a bit annoying (seeing a 13-hour time difference in the mysql client, but no issue on the web front end), it can’t be tolerated any longer.
mysql server wrong or SQLyog client wrong
SQLyog is on the local machine, and mysql server is remote; we can use Wireshark to capture packets to see if the return from mysql is correct.
On Wireshark, choose the correct network card, set the capture expression to: tcp port 3306, then start capturing, and execute the select statement on SQLyog.
SELECT Ftask_id,Fcreate_time FROM t_task ORDER BY Fcreate_time DESC LIMIT 1;
Then, back on our Wireshark, we captured many packets:
/>
Then, simply right-click on one, track flow –tcp stream, and all packets on this tcp connection will be displayed in ASCII. Generally, mysql packets are plaintext where you can directly see the SQL statements and returned results. However, for reasons unknown, SQLyog on my machine, possibly due to a high version, shows only a few statements in plaintext with others not visible in plaintext.
But for now, we don’t have time to tussle with this client, I’ll capture packets directly on the application server to see what mysql server returns.
The TCP dump statement above shows how to capture packets on port 3306, regardless of whether port 3306 is the source or destination port. Then, relevant packets are written into 3306.pcap, and using SZ transfer to a Windows machine, they can be analyzed with Wireshark.
Notice in the image above, the mysql return has issues, first throwing the blame onto mysql.
But, mysql is just storage. Since the stored data is problematic, doesn’t it suggest that maybe something was wrong with our writing?
mysql server: Who wrote an incorrect time for me, step up
It’s quite embarrassing, this time was written by our server. So, we can only continue capturing packets as shown in the image above:
This time, we need to catch it in the act and capture the written packets. Of course, for explanatory purposes here, I have already captured the task.
Indeed, the writing has issues, indicating a problem with the program. Let’s take a look at the mybatis logger recorded SQL logs.
But in the mybatis log, the recorded time is correct, at 9 PM.
Okay, let’s piece it together: our program creates a new date, mybatis writes it, with the logged time at 9 PM no problem; but in the end, the packet sent to the mysql server is 13 hours later.
So what does that mean? Perhaps there’s an issue with the mysql connection. I checked the local code configuration file.
commondb:
database: url: jdbc:mysql://xxxxxx:3306/xxxx?characterEncoding=utf8&zeroDateTimeBehavior=convertToNull&useTimezone=true&serverTimezone=GMT%2B8Look at this configuration, useTimezone=true&serverTimezone=GMT%2B8, clearly seems off; what timezone and what GMT?
Initially, I thought this was the issue; however, here our program and configuration are separately packaged and deployed, which you can think of as a configuration center.
I reviewed the online configuration, and it seemed fine, that is:
commondb:
database: url: jdbc:mysql://xxxxxx:3306/xxxx?characterEncoding=utf8&zeroDateTimeBehavior=convertToNullOriginally, there was nothing about timezone.
I had suspicions: is the java program currently running on the server, did it have problems with commondb.database.url? I considered multiple methods:
1. Since it was spring boot, initially used http://xx.xx.xx.xx:8080/actuator/env to check, found it inaccessible. Later discovered, our program didn’t include the spring boot actuator jar, so gave up.
2. Locally, using jconsole, jvisualvm to connect to this running java program.
How does this work? Firstly, this running program needs the following JVM parameters enabled:
-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false
Then, you can connect with jconsole/jvisualvm.
Refer to a previous blog of mine: https://www.cnblogs.com/grey-wolf/p/9235073.html
Though it’s random, sometimes it connects, sometimes not. This time it didn’t, even after capturing jconsole trying to connect to the remote java program.
Packet filtering statement: tcp port 9999.
The captured packet displays over TCP protocol, realistically, if we know the application layer communication protocol, it can manually right-click—decode as—and select rmi,
Yes, the built-in Java RMI allows viewing additional information.
Of course, notwithstanding the additional info, I still couldn’t figure out why jconsole failed to connect. Abandoning this.
Jconsole didn’t work; ultimately, I had to try Arthas from Alibaba, once connected to that java program, only able to view environment variables, System Properties, etc., which seemed unrelated to what we wanted to see.
Remember, we wanted to see the value of commondb.database.url, after thinking a while, could only address it brutally; apparently, this property was injected into a bean, Datasource, seeing the bean’s value wasn’t simple:
@Bean(name = DATA_SOURCE)
@ConfigurationProperties(prefix = DB_CONFIG_PREFIX) @Primary public DataSource omsDbDatabase() { DataSource build = DataSourceBuilder.create().build(); return build; }So, ultimately, resorted to jmap, dumping heap memory, then used Eclipse MemoryAnalyzer for analysis.
OQL if unfamiliar, delve into it; anyway, it’s search class objects in memory.
Configuration isn’t flawed; So where’s the problem?
It’s only after that realization, given the online java program’s configuration wasn’t problematic yet exhibits this timezone problem, does my local setup suffer the same? (rationally, should’ve considered earlier but was hindsight) Testing locally bore similar behavior, hence debugging was feasible.
Temporarily halted deeper debugging; after eliminating numerous factors, it remained peculiar why my colleague’s program maintained correct time when sending to mysql server, whereas mine had issues. Hence, comparing the mysql-connector-java dependencies of both, a discrepancy became apparent.
mysql mysql-connector-java 8.0.16My colleague used 5.1.41, and why, mine so high, at 8.0. I tested changing to 5.1.41, which made the time sent to mysql server correct.
Explanations Online
Finally having found a probable answer, I leisurely searched for solutions online. Surely, many having upgraded faced this too, and sought answers.
Here’s one, where upgrading mysql-connector-java to 8.0 caused time differences when saving to the database:
https://blog.csdn.net/valsong/article/details/102582582
The exact root cause hasn’t been meticulously examined, but the overall troubleshooting process suffices.